[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:38.653330 25576 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.250.62:37405
I20260812 06:16:38.654454 25576 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:38.655126 25576 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.662753 25582 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.662693 25583 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.662873 25576 server_base.cc:1061] running on GCE node
W20260812 06:16:38.662982 25585 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.663522 25576 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.663627 25576 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.663717 25576 hybrid_clock.cc:648] HybridClock initialized: now 1786515398663707 us; error 0 us; skew 500 ppm
I20260812 06:16:38.665999 25576 webserver.cc:533] Webserver started at http://127.24.250.62:37039/ using document root <none> and password file <none>
I20260812 06:16:38.666630 25576 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.666801 25576 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.667152 25576 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.669052 25576 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/master-0-root/instance:
uuid: "ee0f17e91f62485d9209b84e6187fab7"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-csg5"
I20260812 06:16:38.673429 25576 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.000s	sys 0.006s
I20260812 06:16:38.676079 25591 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.677418 25576 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.000s
I20260812 06:16:38.677549 25576 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/master-0-root
uuid: "ee0f17e91f62485d9209b84e6187fab7"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-csg5"
I20260812 06:16:38.677656 25576 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.707782 25576 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.708598 25576 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:38.708753 25576 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.717731 25576 rpc_server.cc:307] RPC server started. Bound to: 127.24.250.62:37405
I20260812 06:16:38.717765 25654 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.250.62:37405 every 8 connection(s)
I20260812 06:16:38.720443 25655 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.726734 25655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: Bootstrap starting.
I20260812 06:16:38.729344 25655 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.730424 25655 log.cc:826] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:38.732666 25655 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: No bootstrap required, opened a new log
I20260812 06:16:38.736037 25655 raft_consensus.cc:359] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER }
I20260812 06:16:38.736292 25655 raft_consensus.cc:385] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.736416 25655 raft_consensus.cc:740] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ee0f17e91f62485d9209b84e6187fab7, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.737104 25655 consensus_queue.cc:260] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER }
I20260812 06:16:38.737315 25655 raft_consensus.cc:399] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.737416 25655 raft_consensus.cc:493] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.737586 25655 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.738605 25655 raft_consensus.cc:515] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER }
I20260812 06:16:38.739187 25655 leader_election.cc:304] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: ee0f17e91f62485d9209b84e6187fab7; no voters: 
I20260812 06:16:38.739588 25655 leader_election.cc:290] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.739802 25658 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.740083 25658 raft_consensus.cc:697] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 1 LEADER]: Becoming Leader. State: Replica: ee0f17e91f62485d9209b84e6187fab7, State: Running, Role: LEADER
I20260812 06:16:38.740585 25658 consensus_queue.cc:237] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER }
I20260812 06:16:38.740796 25655 sys_catalog.cc:565] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:38.743137 25660 sys_catalog.cc:455] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ee0f17e91f62485d9209b84e6187fab7. Latest consensus state: current_term: 1 leader_uuid: "ee0f17e91f62485d9209b84e6187fab7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER } }
I20260812 06:16:38.743165 25659 sys_catalog.cc:455] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ee0f17e91f62485d9209b84e6187fab7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ee0f17e91f62485d9209b84e6187fab7" member_type: VOTER } }
I20260812 06:16:38.743273 25659 sys_catalog.cc:458] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.743355 25576 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:38.743273 25660 sys_catalog.cc:458] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [sys.catalog]: This master's current role is: LEADER
W20260812 06:16:38.745674 25674 catalog_manager.cc:1594] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:38.745754 25674 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:38.745841 25675 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:38.746645 25675 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:38.752331 25675 catalog_manager.cc:1383] Generated new cluster ID: 9890e64c9fed4cb999b2ddadd4ce6130
I20260812 06:16:38.752426 25675 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:38.777969 25675 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:38.779304 25675 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:38.797747 25675 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: Generated new TSK 0
I20260812 06:16:38.798516 25675 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:38.808738 25576 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.812546 25680 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.812814 25682 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.812819 25679 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.813102 25576 server_base.cc:1061] running on GCE node
I20260812 06:16:38.813339 25576 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.813383 25576 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.813401 25576 hybrid_clock.cc:648] HybridClock initialized: now 1786515398813401 us; error 0 us; skew 500 ppm
I20260812 06:16:38.814640 25576 webserver.cc:533] Webserver started at http://127.24.250.1:40737/ using document root <none> and password file <none>
I20260812 06:16:38.814894 25576 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.814949 25576 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.815048 25576 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.815488 25576 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/instance:
uuid: "bbcbbc07598c416db259b17a36824ec8"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-csg5"
I20260812 06:16:38.817152 25576 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:38.818212 25687 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.818470 25576 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:38.818547 25576 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root
uuid: "bbcbbc07598c416db259b17a36824ec8"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-csg5"
I20260812 06:16:38.818687 25576 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.833164 25576 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.833736 25576 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.834375 25576 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:38.835428 25576 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:38.835487 25576 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.835563 25576 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:38.835619 25576 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.843225 25576 rpc_server.cc:307] RPC server started. Bound to: 127.24.250.1:33407
I20260812 06:16:38.843439 25762 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.250.1:33407 every 8 connection(s)
I20260812 06:16:38.854282 25763 heartbeater.cc:344] Connected to a master server at 127.24.250.62:37405
I20260812 06:16:38.854573 25763 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:38.855228 25763 heartbeater.cc:507] Master 127.24.250.62:37405 requested a full tablet report, sending...
I20260812 06:16:38.856724 25613 ts_manager.cc:194] Registered new tserver with Master: bbcbbc07598c416db259b17a36824ec8 (127.24.250.1:33407)
I20260812 06:16:38.857448 25576 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013439723s
I20260812 06:16:38.858018 25613 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54918
I20260812 06:16:38.868211 25613 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54934:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:38.883033 25722 tablet_service.cc:1511] Processing CreateTablet for tablet 9e410a38067541a789d5d7dfc3b28acb (DEFAULT_TABLE table=heavy-update-compaction-test [id=91316821338c47dfa1c894289869f7db]), partition=
I20260812 06:16:38.883548 25722 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9e410a38067541a789d5d7dfc3b28acb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.886976 25775 tablet_bootstrap.cc:492] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Bootstrap starting.
I20260812 06:16:38.887979 25775 tablet_bootstrap.cc:654] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.889403 25775 tablet_bootstrap.cc:492] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: No bootstrap required, opened a new log
I20260812 06:16:38.889552 25775 ts_tablet_manager.cc:1403] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:38.890059 25775 raft_consensus.cc:359] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbcbbc07598c416db259b17a36824ec8" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 33407 } }
I20260812 06:16:38.890210 25775 raft_consensus.cc:385] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.890249 25775 raft_consensus.cc:740] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bbcbbc07598c416db259b17a36824ec8, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.890422 25775 consensus_queue.cc:260] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbcbbc07598c416db259b17a36824ec8" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 33407 } }
I20260812 06:16:38.890604 25775 raft_consensus.cc:399] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.890740 25775 raft_consensus.cc:493] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.890875 25775 raft_consensus.cc:3060] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.891741 25775 raft_consensus.cc:515] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbcbbc07598c416db259b17a36824ec8" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 33407 } }
I20260812 06:16:38.891935 25775 leader_election.cc:304] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: bbcbbc07598c416db259b17a36824ec8; no voters: 
I20260812 06:16:38.892253 25775 leader_election.cc:290] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.892400 25777 raft_consensus.cc:2804] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.892590 25777 raft_consensus.cc:697] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 1 LEADER]: Becoming Leader. State: Replica: bbcbbc07598c416db259b17a36824ec8, State: Running, Role: LEADER
I20260812 06:16:38.892716 25775 ts_tablet_manager.cc:1434] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:16:38.892809 25777 consensus_queue.cc:237] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbcbbc07598c416db259b17a36824ec8" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 33407 } }
I20260812 06:16:38.893011 25763 heartbeater.cc:499] Master 127.24.250.62:37405 was elected leader, sending a full tablet report...
I20260812 06:16:38.895928 25613 catalog_manager.cc:5719] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 reported cstate change: term changed from 0 to 1, leader changed from <none> to bbcbbc07598c416db259b17a36824ec8 (127.24.250.1). New cstate: current_term: 1 leader_uuid: "bbcbbc07598c416db259b17a36824ec8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbcbbc07598c416db259b17a36824ec8" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 33407 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.969043 25576 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.025s	sys 0.005s
I20260812 06:16:39.094614 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb): perf score=15.086190
I20260812 06:16:39.273013 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.178s	user 0.133s	sys 0.033s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":219,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1007,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40960,"lbm_writes_lt_1ms":657,"mutex_wait_us":3,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":143,"threads_started":1,"update_count":1450}
I20260812 06:16:39.274264 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling LogGCOp(9e410a38067541a789d5d7dfc3b28acb): free 20743880 bytes of WAL
I20260812 06:16:39.274677 25692 log_reader.cc:385] T 9e410a38067541a789d5d7dfc3b28acb: removed 2 log segments from log reader
I20260812 06:16:39.274765 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000001 (ops 1-6)
I20260812 06:16:39.274830 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000002 (ops 7-11)
I20260812 06:16:39.280311 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: LogGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:16:39.280867 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb): 12719217 bytes on disk
I20260812 06:16:39.281637 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.282112 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:39.299536 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.300216 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:39.444805 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.144s	user 0.103s	sys 0.041s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262038,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1156,"lbm_read_time_us":9241,"lbm_reads_lt_1ms":450,"lbm_write_time_us":27415,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":335,"threads_started":5,"update_count":1950}
I20260812 06:16:39.445652 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:39.489017 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.043s	user 0.015s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19071,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.489713 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:39.506088 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.506861 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:39.639111 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.132s	user 0.095s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":8499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26375,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:16:39.639912 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:39.679334 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.039s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16851,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.679865 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:39.696514 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.697156 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:39.829751 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.132s	user 0.099s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":8068,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26912,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2000}
I20260812 06:16:39.830543 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=11.118625
I20260812 06:16:39.879786 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.049s	user 0.028s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18598,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.880481 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:39.892009 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.892549 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:40.062115 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.169s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":11897,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27902,"lbm_writes_lt_1ms":443,"mutex_wait_us":114,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:16:40.062918 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:40.108625 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.046s	user 0.037s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17318,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.109182 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:40.121039 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.121699 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:40.252676 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.131s	user 0.115s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1380,"lbm_read_time_us":8075,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25260,"lbm_writes_lt_1ms":443,"mutex_wait_us":422,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:40.253504 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:40.296185 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.042s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15592,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.296813 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:40.308705 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.309486 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:40.438233 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.129s	user 0.087s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":8917,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26642,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:40.439064 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:40.489158 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.050s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15347,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.489768 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:40.502537 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.503229 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:40.628688 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.125s	user 0.100s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":7632,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26423,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:16:40.629402 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:40.687463 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.058s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17239,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.688081 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:40.699276 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.699885 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:40.750442 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.050s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":326,"dirs.run_wall_time_us":1765,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2102,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:40.751652 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling LogGCOp(9e410a38067541a789d5d7dfc3b28acb): free 128867446 bytes of WAL
I20260812 06:16:40.752000 25692 log_reader.cc:385] T 9e410a38067541a789d5d7dfc3b28acb: removed 13 log segments from log reader
I20260812 06:16:40.752089 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000003 (ops 12-16)
I20260812 06:16:40.752156 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000004 (ops 17-20)
I20260812 06:16:40.752333 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000005 (ops 21-25)
I20260812 06:16:40.752381 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000006 (ops 26-30)
I20260812 06:16:40.752429 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000007 (ops 31-35)
I20260812 06:16:40.752471 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000008 (ops 36-40)
I20260812 06:16:40.752516 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000009 (ops 41-44)
I20260812 06:16:40.752568 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000010 (ops 45-49)
I20260812 06:16:40.752665 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000011 (ops 50-54)
I20260812 06:16:40.752694 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000012 (ops 55-58)
I20260812 06:16:40.752727 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000013 (ops 59-63)
I20260812 06:16:40.752774 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000014 (ops 64-68)
I20260812 06:16:40.752817 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000015 (ops 69-73)
I20260812 06:16:40.781366 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: LogGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:40.781857 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb): 482 bytes on disk
I20260812 06:16:40.782322 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.783201 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=3.181125
I20260812 06:16:40.795863 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.012s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4923146,"delete_count":0,"lbm_write_time_us":4885,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:16:40.796293 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:40.805727 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3373,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:16:40.806331 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:41.018958 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.212s	user 0.152s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":781,"lbm_read_time_us":13524,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35286,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":32128,"thread_start_us":104,"threads_started":1,"update_count":3000}
I20260812 06:16:41.019690 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:41.096675 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.077s	user 0.037s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29822,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.097285 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:41.110275 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.110877 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:41.310891 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.200s	user 0.149s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":13039,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37811,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:16:41.311740 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=11.118625
I20260812 06:16:41.366374 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.054s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17631,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.367185 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=3.181125
I20260812 06:16:41.381008 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4676998,"delete_count":0,"lbm_write_time_us":5525,"lbm_writes_lt_1ms":117,"reinsert_count":0,"update_count":570}
I20260812 06:16:41.381583 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.196750
I20260812 06:16:41.391940 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3567,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:16:41.393028 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:41.611893 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.219s	user 0.150s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774789,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":256,"lbm_read_time_us":14004,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35812,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:41.612844 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:41.682209 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.069s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20648,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.682950 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:41.694370 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.694943 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:41.881918 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.187s	user 0.136s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":888,"lbm_read_time_us":12810,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31155,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:41.882872 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=11.118625
I20260812 06:16:41.921362 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.038s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16120,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.922183 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:41.944211 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.022s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6445,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.944762 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:42.112277 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.167s	user 0.127s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":456,"lbm_read_time_us":9365,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26589,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":2000}
I20260812 06:16:42.112866 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=11.118625
I20260812 06:16:42.160300 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20795,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.161054 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:42.178179 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5413,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.179268 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:42.320266 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.141s	user 0.110s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":490,"lbm_read_time_us":9906,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27232,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:16:42.321117 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:42.367632 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.046s	user 0.012s	sys 0.031s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20914,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.368403 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:42.384253 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.385040 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:42.419015 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":2804,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2108,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:42.419994 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling LogGCOp(9e410a38067541a789d5d7dfc3b28acb): free 120553356 bytes of WAL
I20260812 06:16:42.420274 25692 log_reader.cc:385] T 9e410a38067541a789d5d7dfc3b28acb: removed 12 log segments from log reader
I20260812 06:16:42.420326 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000016 (ops 74-78)
I20260812 06:16:42.420361 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000017 (ops 79-83)
I20260812 06:16:42.420432 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000018 (ops 84-88)
I20260812 06:16:42.420485 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000019 (ops 89-92)
I20260812 06:16:42.420533 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000020 (ops 93-97)
I20260812 06:16:42.420594 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000021 (ops 98-102)
I20260812 06:16:42.420652 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000022 (ops 103-107)
I20260812 06:16:42.420717 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000023 (ops 108-112)
I20260812 06:16:42.420763 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000024 (ops 113-117)
I20260812 06:16:42.420805 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000025 (ops 118-122)
I20260812 06:16:42.420847 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000026 (ops 123-126)
I20260812 06:16:42.420890 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000027 (ops 127-131)
I20260812 06:16:42.451524 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: LogGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:42.452241 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb): 463 bytes on disk
I20260812 06:16:42.452859 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.453542 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=3.181125
I20260812 06:16:42.467518 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:42.468058 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:42.479490 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.480299 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:42.688001 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.207s	user 0.120s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":461,"lbm_read_time_us":13712,"lbm_reads_lt_1ms":674,"lbm_write_time_us":43873,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:16:42.688830 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=11.118625
I20260812 06:16:42.731556 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.042s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18903,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.732409 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:42.757782 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.025s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":6463,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:16:42.758312 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:42.769160 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:16:42.769749 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:42.941269 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.171s	user 0.146s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":217,"lbm_read_time_us":11565,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32860,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:16:42.942859 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:42.989171 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.046s	user 0.021s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19152,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.989892 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:43.006354 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.006917 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:43.168509 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.161s	user 0.104s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1669,"lbm_read_time_us":11694,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26793,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":98560,"update_count":2000}
I20260812 06:16:43.169266 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=10.126437
I20260812 06:16:43.206907 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.037s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16106,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.207672 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:43.227948 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.228653 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:43.397615 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.169s	user 0.121s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":452,"lbm_read_time_us":8434,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24005,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.398226 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:43.455034 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.057s	user 0.040s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26756,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.455865 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:43.470813 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.471494 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:43.637681 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.166s	user 0.123s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":10191,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32377,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:16:43.638420 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:43.693759 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.055s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24287,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.694435 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:43.707233 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.708384 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:43.876573 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.168s	user 0.138s	sys 0.014s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":9550,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31940,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:16:43.877347 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:43.944869 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.067s	user 0.040s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25234,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.945575 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:43.962997 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.963712 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:43.992808 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushMRSOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1729,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1873,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:43.993552 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling LogGCOp(9e410a38067541a789d5d7dfc3b28acb): free 121006753 bytes of WAL
I20260812 06:16:43.993808 25692 log_reader.cc:385] T 9e410a38067541a789d5d7dfc3b28acb: removed 12 log segments from log reader
I20260812 06:16:43.993854 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000028 (ops 132-136)
I20260812 06:16:43.993883 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000029 (ops 137-141)
I20260812 06:16:43.993950 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000030 (ops 142-146)
I20260812 06:16:43.993995 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000031 (ops 147-151)
I20260812 06:16:43.994060 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000032 (ops 152-156)
I20260812 06:16:43.994120 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000033 (ops 157-161)
I20260812 06:16:43.994158 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000034 (ops 162-166)
I20260812 06:16:43.994200 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000035 (ops 167-171)
I20260812 06:16:43.994235 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000036 (ops 172-176)
I20260812 06:16:43.994273 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000037 (ops 177-180)
I20260812 06:16:43.994313 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000038 (ops 181-185)
I20260812 06:16:43.994356 25692 log.cc:1079] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/9e410a38067541a789d5d7dfc3b28acb/wal-000000039 (ops 186-190)
I20260812 06:16:44.022878 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: LogGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:44.023412 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=3.181125
I20260812 06:16:44.036868 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4688,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:44.037379 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb): 472 bytes on disk
I20260812 06:16:44.037809 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: UndoDeltaBlockGCOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.038323 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=2.188937
I20260812 06:16:44.048820 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.049580 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb): perf score=1.000000
I20260812 06:16:44.252357 25576 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.283s	user 1.965s	sys 0.146s
I20260812 06:16:44.287122 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: MajorDeltaCompactionOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.237s	user 0.149s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16201,"lbm_reads_lt_1ms":770,"lbm_write_time_us":44731,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:16:44.287647 25764 maintenance_manager.cc:419] P bbcbbc07598c416db259b17a36824ec8: Scheduling FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb): perf score=14.095187
I20260812 06:16:44.331439 25576 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.003s	sys 0.000s
I20260812 06:16:44.332773 25576 tablet_server.cc:179] TabletServer@127.24.250.1:0 shutting down...
I20260812 06:16:44.376556 25692 maintenance_manager.cc:643] P bbcbbc07598c416db259b17a36824ec8: FlushDeltaMemStoresOp(9e410a38067541a789d5d7dfc3b28acb) complete. Timing: real 0.089s	user 0.026s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.377460 25576 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:44.378067 25576 tablet_replica.cc:333] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8: stopping tablet replica
I20260812 06:16:44.378372 25576 raft_consensus.cc:2243] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:44.378712 25576 raft_consensus.cc:2272] T 9e410a38067541a789d5d7dfc3b28acb P bbcbbc07598c416db259b17a36824ec8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:44.394516 25576 tablet_server.cc:196] TabletServer@127.24.250.1:0 shutdown complete.
I20260812 06:16:44.400142 25576 master.cc:562] Master@127.24.250.62:37405 shutting down...
I20260812 06:16:44.404728 25576 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:44.404955 25576 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:44.405041 25576 tablet_replica.cc:333] T 00000000000000000000000000000000 P ee0f17e91f62485d9209b84e6187fab7: stopping tablet replica
I20260812 06:16:44.418047 25576 master.cc:584] Master@127.24.250.62:37405 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5851 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:44.504065 25576 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.250.62:41923
I20260812 06:16:44.504492 25576 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:44.507380 25802 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:44.507433 25798 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:44.507416 25576 server_base.cc:1061] running on GCE node
W20260812 06:16:44.507361 25799 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:44.507977 25576 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:44.508029 25576 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:44.508046 25576 hybrid_clock.cc:648] HybridClock initialized: now 1786515404508046 us; error 0 us; skew 500 ppm
I20260812 06:16:44.509028 25576 webserver.cc:533] Webserver started at http://127.24.250.62:43095/ using document root <none> and password file <none>
I20260812 06:16:44.509176 25576 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:44.509297 25576 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:44.509359 25576 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:44.509729 25576 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/master-0-root/instance:
uuid: "5e87c20ab6f744019baf4f6feeafa4ad"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-csg5"
I20260812 06:16:44.511650 25576 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:44.512766 25808 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.513193 25576 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:44.513273 25576 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/master-0-root
uuid: "5e87c20ab6f744019baf4f6feeafa4ad"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-csg5"
I20260812 06:16:44.513412 25576 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:44.521473 25576 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:44.521868 25576 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:44.527004 25576 rpc_server.cc:307] RPC server started. Bound to: 127.24.250.62:41923
I20260812 06:16:44.529006 25866 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.250.62:41923 every 8 connection(s)
I20260812 06:16:44.529204 25867 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:44.544940 25867 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad: Bootstrap starting.
I20260812 06:16:44.546110 25867 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:44.547458 25867 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad: No bootstrap required, opened a new log
I20260812 06:16:44.547974 25867 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER }
I20260812 06:16:44.548105 25867 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:44.548153 25867 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5e87c20ab6f744019baf4f6feeafa4ad, State: Initialized, Role: FOLLOWER
I20260812 06:16:44.548478 25867 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER }
I20260812 06:16:44.548591 25867 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:44.548650 25867 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:44.548707 25867 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:44.549582 25867 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER }
I20260812 06:16:44.549746 25867 leader_election.cc:304] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 5e87c20ab6f744019baf4f6feeafa4ad; no voters: 
I20260812 06:16:44.550016 25867 leader_election.cc:290] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:44.550201 25871 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:44.550537 25871 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 1 LEADER]: Becoming Leader. State: Replica: 5e87c20ab6f744019baf4f6feeafa4ad, State: Running, Role: LEADER
I20260812 06:16:44.550571 25867 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:44.550732 25871 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER }
I20260812 06:16:44.551342 25873 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5e87c20ab6f744019baf4f6feeafa4ad. Latest consensus state: current_term: 1 leader_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER } }
I20260812 06:16:44.551545 25873 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:44.551563 25872 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e87c20ab6f744019baf4f6feeafa4ad" member_type: VOTER } }
I20260812 06:16:44.551676 25872 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:44.552107 25880 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:44.553043 25880 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:44.553433 25576 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:44.555626 25880 catalog_manager.cc:1383] Generated new cluster ID: 57169eaf6288410b95bd74d516fc37d0
I20260812 06:16:44.555776 25880 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:44.581327 25880 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:44.582007 25880 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:44.597890 25880 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad: Generated new TSK 0
I20260812 06:16:44.598153 25880 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:44.618639 25576 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:44.621214 25890 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:44.621307 25891 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:44.621507 25893 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:44.621552 25576 server_base.cc:1061] running on GCE node
I20260812 06:16:44.621780 25576 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:44.621829 25576 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:44.621845 25576 hybrid_clock.cc:648] HybridClock initialized: now 1786515404621845 us; error 0 us; skew 500 ppm
I20260812 06:16:44.623041 25576 webserver.cc:533] Webserver started at http://127.24.250.1:42897/ using document root <none> and password file <none>
I20260812 06:16:44.623267 25576 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:44.623348 25576 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:44.623415 25576 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:44.623880 25576 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/instance:
uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-csg5"
I20260812 06:16:44.625752 25576 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:44.627682 25899 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.628029 25576 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:44.628144 25576 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root
uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435"
format_stamp: "Formatted at 2026-08-12 06:16:44 on dist-test-slave-csg5"
I20260812 06:16:44.628259 25576 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:44.653697 25576 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:44.654153 25576 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:44.654511 25576 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:44.655074 25576 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:44.655141 25576 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.655194 25576 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:44.655246 25576 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:44.660184 25576 rpc_server.cc:307] RPC server started. Bound to: 127.24.250.1:39417
I20260812 06:16:44.660248 25971 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.250.1:39417 every 8 connection(s)
I20260812 06:16:44.670646 25973 heartbeater.cc:344] Connected to a master server at 127.24.250.62:41923
I20260812 06:16:44.670821 25973 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:44.671206 25973 heartbeater.cc:507] Master 127.24.250.62:41923 requested a full tablet report, sending...
I20260812 06:16:44.672156 25826 ts_manager.cc:194] Registered new tserver with Master: c4cf21ef0b8e49d4b0f9124bb25a3435 (127.24.250.1:39417)
I20260812 06:16:44.673031 25826 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49632
I20260812 06:16:44.673158 25576 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012458089s
I20260812 06:16:44.682726 25826 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49636:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:44.694082 25930 tablet_service.cc:1511] Processing CreateTablet for tablet f6a1f2e3fb674bee919364a113e4a460 (DEFAULT_TABLE table=heavy-update-compaction-test [id=807f366e66594c01aee229afd71de0f6]), partition=
I20260812 06:16:44.694409 25930 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f6a1f2e3fb674bee919364a113e4a460. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:44.697124 25985 tablet_bootstrap.cc:492] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Bootstrap starting.
I20260812 06:16:44.698181 25985 tablet_bootstrap.cc:654] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:44.699703 25985 tablet_bootstrap.cc:492] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: No bootstrap required, opened a new log
I20260812 06:16:44.699908 25985 ts_tablet_manager.cc:1403] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:44.700500 25985 raft_consensus.cc:359] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 39417 } }
I20260812 06:16:44.700635 25985 raft_consensus.cc:385] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:44.700692 25985 raft_consensus.cc:740] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c4cf21ef0b8e49d4b0f9124bb25a3435, State: Initialized, Role: FOLLOWER
I20260812 06:16:44.700870 25985 consensus_queue.cc:260] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 39417 } }
I20260812 06:16:44.700985 25985 raft_consensus.cc:399] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:44.701043 25985 raft_consensus.cc:493] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:44.701110 25985 raft_consensus.cc:3060] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:44.702014 25985 raft_consensus.cc:515] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 39417 } }
I20260812 06:16:44.702207 25985 leader_election.cc:304] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: c4cf21ef0b8e49d4b0f9124bb25a3435; no voters: 
I20260812 06:16:44.702539 25985 leader_election.cc:290] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:44.702744 25988 raft_consensus.cc:2804] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:44.703074 25985 ts_tablet_manager.cc:1434] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:44.703085 25988 raft_consensus.cc:697] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 1 LEADER]: Becoming Leader. State: Replica: c4cf21ef0b8e49d4b0f9124bb25a3435, State: Running, Role: LEADER
I20260812 06:16:44.703361 25973 heartbeater.cc:499] Master 127.24.250.62:41923 was elected leader, sending a full tablet report...
I20260812 06:16:44.703498 25988 consensus_queue.cc:237] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 39417 } }
I20260812 06:16:44.705065 25826 catalog_manager.cc:5719] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 reported cstate change: term changed from 0 to 1, leader changed from <none> to c4cf21ef0b8e49d4b0f9124bb25a3435 (127.24.250.1). New cstate: current_term: 1 leader_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c4cf21ef0b8e49d4b0f9124bb25a3435" member_type: VOTER last_known_addr { host: "127.24.250.1" port: 39417 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:44.772680 25576 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.015s	sys 0.012s
I20260812 06:16:44.911417 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460): perf score=15.086190
I20260812 06:16:45.075229 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.163s	user 0.126s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1029,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43627,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:16:45.076486 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling LogGCOp(f6a1f2e3fb674bee919364a113e4a460): free 11976772 bytes of WAL
I20260812 06:16:45.076768 25905 log_reader.cc:385] T f6a1f2e3fb674bee919364a113e4a460: removed 1 log segments from log reader
I20260812 06:16:45.076835 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000001 (ops 1-6)
I20260812 06:16:45.080322 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: LogGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:45.080829 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460): 12308957 bytes on disk
I20260812 06:16:45.081465 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.082074 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:45.100951 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.101497 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:45.265205 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.164s	user 0.123s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":612,"lbm_read_time_us":10272,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29821,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":421,"threads_started":5,"update_count":2000}
I20260812 06:16:45.265827 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:45.322511 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.056s	user 0.044s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23763,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.323539 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:45.339931 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.340548 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:45.489022 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.148s	user 0.119s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":10631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28492,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:16:45.489533 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:45.550096 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.060s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15946,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.550958 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:45.563333 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.563953 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:45.752668 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.188s	user 0.137s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":474,"lbm_read_time_us":13247,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29869,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:16:45.753347 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:45.791932 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.038s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17198,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.792510 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:45.811916 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.019s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.812477 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:45.962882 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.150s	user 0.114s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4064,"lbm_read_time_us":8612,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30568,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":965,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:45.963783 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:46.007543 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.043s	user 0.035s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18795,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.008394 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:46.030556 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.022s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.031361 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:46.164844 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.133s	user 0.121s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1315,"lbm_read_time_us":7901,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28506,"lbm_writes_lt_1ms":443,"mutex_wait_us":375,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:16:46.165786 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:46.217003 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.051s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17599,"lbm_writes_lt_1ms":303,"mutex_wait_us":115,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.217738 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:46.229722 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.230280 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:46.372965 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.142s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":982,"lbm_read_time_us":10049,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26376,"lbm_writes_lt_1ms":443,"mutex_wait_us":413,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:16:46.373617 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=10.126437
I20260812 06:16:46.434250 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.060s	user 0.013s	sys 0.039s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20126,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.434975 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:46.445935 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.446442 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:46.482758 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.036s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":303,"dirs.run_wall_time_us":1717,"drs_written":1,"lbm_read_time_us":132,"lbm_reads_lt_1ms":4,"lbm_write_time_us":4778,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:46.483748 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:46.648550 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.165s	user 0.107s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1005,"lbm_read_time_us":9721,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27565,"lbm_writes_lt_1ms":443,"mutex_wait_us":287,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:16:46.649432 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling LogGCOp(f6a1f2e3fb674bee919364a113e4a460): free 112692356 bytes of WAL
I20260812 06:16:46.649703 25905 log_reader.cc:385] T f6a1f2e3fb674bee919364a113e4a460: removed 11 log segments from log reader
I20260812 06:16:46.649761 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000002 (ops 7-11)
I20260812 06:16:46.649812 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000003 (ops 12-16)
I20260812 06:16:46.649855 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000004 (ops 17-21)
I20260812 06:16:46.649950 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000005 (ops 22-26)
I20260812 06:16:46.650002 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000006 (ops 27-31)
I20260812 06:16:46.650038 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000007 (ops 32-36)
I20260812 06:16:46.650075 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000008 (ops 37-41)
I20260812 06:16:46.650118 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000009 (ops 42-46)
I20260812 06:16:46.650170 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000010 (ops 47-51)
I20260812 06:16:46.650231 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000011 (ops 52-56)
I20260812 06:16:46.650276 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000012 (ops 57-61)
I20260812 06:16:46.679410 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: LogGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:46.680147 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460): 447 bytes on disk
I20260812 06:16:46.680889 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.682024 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:46.735311 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.053s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.736003 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling LogGCOp(f6a1f2e3fb674bee919364a113e4a460): free 12017932 bytes of WAL
I20260812 06:16:46.736228 25905 log_reader.cc:385] T f6a1f2e3fb674bee919364a113e4a460: removed 1 log segments from log reader
I20260812 06:16:46.736325 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000013 (ops 62-66)
I20260812 06:16:46.739717 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: LogGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:46.740267 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:46.770164 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.030s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6469,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.770836 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:46.793695 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.794313 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:47.031724 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.237s	user 0.161s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836254,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":842,"lbm_read_time_us":19456,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37564,"lbm_writes_lt_1ms":643,"mutex_wait_us":77,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:16:47.032398 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:47.101315 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.069s	user 0.022s	sys 0.043s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24549,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.102247 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=3.181125
I20260812 06:16:47.126629 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.024s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6103,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.127236 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:47.138324 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.138996 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:47.371054 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.232s	user 0.161s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836245,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":604,"lbm_read_time_us":16356,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39081,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:16:47.371999 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:47.434762 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.062s	user 0.045s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27899,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.435866 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:47.452236 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.452823 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:47.641033 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.188s	user 0.136s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":12236,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31177,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:16:47.642335 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=15.087375
I20260812 06:16:47.724391 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.082s	user 0.047s	sys 0.017s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":28574,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:47.724960 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=6.157687
I20260812 06:16:47.752872 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.028s	user 0.011s	sys 0.011s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":10443,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:47.753497 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:48.006968 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.253s	user 0.151s	sys 0.087s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":541,"lbm_read_time_us":14781,"lbm_reads_lt_1ms":664,"lbm_write_time_us":41071,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":3000}
I20260812 06:16:48.007814 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=18.063937
I20260812 06:16:48.084407 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.076s	user 0.054s	sys 0.012s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":30723,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:48.084975 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:48.095635 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.096231 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:48.128185 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.032s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":211,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1900,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1616,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:48.128955 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling LogGCOp(f6a1f2e3fb674bee919364a113e4a460): free 112692368 bytes of WAL
I20260812 06:16:48.129231 25905 log_reader.cc:385] T f6a1f2e3fb674bee919364a113e4a460: removed 11 log segments from log reader
I20260812 06:16:48.129284 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000014 (ops 67-71)
I20260812 06:16:48.129318 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000015 (ops 72-76)
I20260812 06:16:48.129395 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000016 (ops 77-81)
I20260812 06:16:48.129470 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000017 (ops 82-86)
I20260812 06:16:48.129539 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000018 (ops 87-91)
I20260812 06:16:48.129642 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000019 (ops 92-96)
I20260812 06:16:48.129720 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000020 (ops 97-101)
I20260812 06:16:48.129797 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000021 (ops 102-106)
I20260812 06:16:48.129869 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000022 (ops 107-111)
I20260812 06:16:48.129918 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000023 (ops 112-116)
I20260812 06:16:48.129964 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000024 (ops 117-121)
I20260812 06:16:48.158102 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: LogGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:48.158599 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=3.181125
I20260812 06:16:48.176245 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.017s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:48.176734 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:48.186992 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.187486 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460): 462 bytes on disk
I20260812 06:16:48.188130 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":135,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.189083 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:48.449743 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.260s	user 0.190s	sys 0.067s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041186,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2870,"lbm_read_time_us":18982,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44485,"lbm_writes_lt_1ms":843,"mutex_wait_us":80,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":19328,"thread_start_us":97,"threads_started":1,"update_count":4000}
I20260812 06:16:48.450657 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=18.063937
I20260812 06:16:48.531988 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.081s	user 0.040s	sys 0.040s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":36086,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:48.532552 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:48.556695 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.024s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.557617 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:48.738054 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.180s	user 0.160s	sys 0.020s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":13844,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35208,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:16:48.739121 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:48.794029 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.055s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.794785 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:48.810976 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.811581 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:48.999943 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.188s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":495,"lbm_read_time_us":10734,"lbm_reads_lt_1ms":568,"lbm_write_time_us":34555,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:49.000696 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:49.058516 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.058s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.059197 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:49.226579 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.167s	user 0.135s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1428,"lbm_read_time_us":11539,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28798,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:16:49.227476 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=11.118625
I20260812 06:16:49.277777 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":23494,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.278383 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:49.304046 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.025s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.304692 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:49.316592 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.317330 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:49.511673 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.194s	user 0.122s	sys 0.069s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":642,"lbm_read_time_us":11886,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29425,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:16:49.512302 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=14.095187
I20260812 06:16:49.565593 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.053s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23433,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.566344 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:49.580097 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.580791 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:49.762328 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.181s	user 0.127s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":433,"lbm_read_time_us":9911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35490,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:16:49.762938 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=11.118625
I20260812 06:16:49.801082 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16744,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.801853 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:49.816794 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.015s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4845,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.817437 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:49.874320 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushMRSOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.057s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316414,"cfile_init":1,"dirs.queue_time_us":215,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":2156,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3026,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:49.875252 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling LogGCOp(f6a1f2e3fb674bee919364a113e4a460): free 132571558 bytes of WAL
I20260812 06:16:49.875581 25905 log_reader.cc:385] T f6a1f2e3fb674bee919364a113e4a460: removed 13 log segments from log reader
I20260812 06:16:49.875653 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000025 (ops 122-126)
I20260812 06:16:49.875694 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000026 (ops 127-130)
I20260812 06:16:49.875728 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000027 (ops 131-135)
I20260812 06:16:49.875753 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000028 (ops 136-140)
I20260812 06:16:49.875777 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000029 (ops 141-145)
I20260812 06:16:49.875799 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000030 (ops 146-150)
I20260812 06:16:49.875823 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000031 (ops 151-155)
I20260812 06:16:49.875845 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000032 (ops 156-160)
I20260812 06:16:49.875871 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000033 (ops 161-165)
I20260812 06:16:49.875906 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000034 (ops 166-170)
I20260812 06:16:49.875929 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000035 (ops 171-175)
I20260812 06:16:49.875952 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000036 (ops 176-180)
I20260812 06:16:49.875981 25905 log.cc:1079] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: Deleting log segment in path: /tmp/dist-test-taskirO8Rq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398641216-25576-0/minicluster-data/ts-0-root/wals/f6a1f2e3fb674bee919364a113e4a460/wal-000000037 (ops 181-184)
I20260812 06:16:49.910784 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: LogGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.035s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:16:49.911341 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460): 493 bytes on disk
I20260812 06:16:49.912146 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: UndoDeltaBlockGCOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":140,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.912855 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=6.157687
I20260812 06:16:49.949440 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.036s	user 0.011s	sys 0.019s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9337,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.950115 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:49.961733 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.962445 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:50.207747 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.245s	user 0.167s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1048,"lbm_read_time_us":16870,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38099,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":121,"threads_started":1,"update_count":3500}
I20260812 06:16:50.208823 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=15.087375
I20260812 06:16:50.280619 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.072s	user 0.050s	sys 0.020s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":34688,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:16:50.281208 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:50.298130 25576 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.525s	user 2.015s	sys 0.218s
I20260812 06:16:50.299754 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.018s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.300251 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460): perf score=2.188937
I20260812 06:16:50.311517 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: FlushDeltaMemStoresOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":500}
I20260812 06:16:50.312017 25974 maintenance_manager.cc:419] P c4cf21ef0b8e49d4b0f9124bb25a3435: Scheduling MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460): perf score=1.000000
I20260812 06:16:50.385404 25576 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.002s	sys 0.000s
I20260812 06:16:50.386077 25576 tablet_server.cc:179] TabletServer@127.24.250.1:0 shutting down...
I20260812 06:16:50.479966 25905 maintenance_manager.cc:643] P c4cf21ef0b8e49d4b0f9124bb25a3435: MajorDeltaCompactionOp(f6a1f2e3fb674bee919364a113e4a460) complete. Timing: real 0.168s	user 0.120s	sys 0.048s Metrics: {"cfile_cache_hit":233,"cfile_cache_hit_bytes":9480327,"cfile_cache_miss":400,"cfile_cache_miss_bytes":19355914,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":673,"lbm_read_time_us":9222,"lbm_reads_lt_1ms":432,"lbm_write_time_us":32900,"lbm_writes_lt_1ms":643,"mutex_wait_us":93,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:16:50.480732 25576 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:50.481067 25576 tablet_replica.cc:333] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435: stopping tablet replica
I20260812 06:16:50.481297 25576 raft_consensus.cc:2243] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.481504 25576 raft_consensus.cc:2272] T f6a1f2e3fb674bee919364a113e4a460 P c4cf21ef0b8e49d4b0f9124bb25a3435 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.485889 25576 tablet_server.cc:196] TabletServer@127.24.250.1:0 shutdown complete.
I20260812 06:16:50.534443 25576 master.cc:562] Master@127.24.250.62:41923 shutting down...
I20260812 06:16:50.538893 25576 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.539108 25576 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.539170 25576 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5e87c20ab6f744019baf4f6feeafa4ad: stopping tablet replica
I20260812 06:16:50.552217 25576 master.cc:584] Master@127.24.250.62:41923 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6139 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11992 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test suite ran. (11992 ms total)
[  PASSED  ] 2 tests.
