[==========] 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:20:15.810408 31458 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.184.190:38505
I20260812 06:20:15.811609 31458 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:20:15.812270 31458 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:15.819497 31472 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:20:15.819528 31466 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:20:15.819605 31458 server_base.cc:1061] running on GCE node
W20260812 06:20:15.819841 31465 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:20:15.820359 31458 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.820493 31458 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:20:15.820555 31458 hybrid_clock.cc:648] HybridClock initialized: now 1786515615820552 us; error 0 us; skew 500 ppm
I20260812 06:20:15.822606 31458 webserver.cc:533] Webserver started at http://127.30.184.190:45095/ using document root <none> and password file <none>
I20260812 06:20:15.823182 31458 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.823277 31458 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.823544 31458 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.825299 31458 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/master-0-root/instance:
uuid: "026768a4ad9742659963b8477f753cca"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-h6n0"
I20260812 06:20:15.828920 31458 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:15.831332 31483 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:20:15.832830 31458 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:15.833020 31458 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/master-0-root
uuid: "026768a4ad9742659963b8477f753cca"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-h6n0"
I20260812 06:20:15.833138 31458 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-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:20:15.847174 31458 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.847806 31458 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:20:15.848002 31458 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.856760 31458 rpc_server.cc:307] RPC server started. Bound to: 127.30.184.190:38505
I20260812 06:20:15.856801 31559 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.184.190:38505 every 8 connection(s)
I20260812 06:20:15.859325 31560 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:20:15.864923 31560 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: Bootstrap starting.
I20260812 06:20:15.867476 31560 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:15.868435 31560 log.cc:826] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:15.870570 31560 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: No bootstrap required, opened a new log
I20260812 06:20:15.873744 31560 raft_consensus.cc:359] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026768a4ad9742659963b8477f753cca" member_type: VOTER }
I20260812 06:20:15.874110 31560 raft_consensus.cc:385] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:15.874209 31560 raft_consensus.cc:740] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 026768a4ad9742659963b8477f753cca, State: Initialized, Role: FOLLOWER
I20260812 06:20:15.874979 31560 consensus_queue.cc:260] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [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: "026768a4ad9742659963b8477f753cca" member_type: VOTER }
I20260812 06:20:15.875162 31560 raft_consensus.cc:399] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:15.875211 31560 raft_consensus.cc:493] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:15.875308 31560 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:15.876351 31560 raft_consensus.cc:515] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026768a4ad9742659963b8477f753cca" member_type: VOTER }
I20260812 06:20:15.876787 31560 leader_election.cc:304] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [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: 026768a4ad9742659963b8477f753cca; no voters: 
I20260812 06:20:15.877099 31560 leader_election.cc:290] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:15.877319 31569 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:15.877620 31569 raft_consensus.cc:697] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 1 LEADER]: Becoming Leader. State: Replica: 026768a4ad9742659963b8477f753cca, State: Running, Role: LEADER
I20260812 06:20:15.878058 31569 consensus_queue.cc:237] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [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: "026768a4ad9742659963b8477f753cca" member_type: VOTER }
I20260812 06:20:15.878230 31560 sys_catalog.cc:565] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:15.880731 31573 sys_catalog.cc:455] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "026768a4ad9742659963b8477f753cca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026768a4ad9742659963b8477f753cca" member_type: VOTER } }
I20260812 06:20:15.880789 31579 sys_catalog.cc:455] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [sys.catalog]: SysCatalogTable state changed. Reason: New leader 026768a4ad9742659963b8477f753cca. Latest consensus state: current_term: 1 leader_uuid: "026768a4ad9742659963b8477f753cca" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "026768a4ad9742659963b8477f753cca" member_type: VOTER } }
I20260812 06:20:15.880882 31573 sys_catalog.cc:458] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.880880 31579 sys_catalog.cc:458] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:15.881839 31586 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:15.881958 31458 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:15.884052 31586 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:15.888819 31586 catalog_manager.cc:1383] Generated new cluster ID: 52ca50e0dede4c70a07971b0eb660f06
I20260812 06:20:15.888895 31586 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:15.907084 31586 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:15.908274 31586 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:15.917511 31586 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: Generated new TSK 0
I20260812 06:20:15.918728 31586 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:15.947007 31458 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:15.951476 31607 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:20:15.951736 31605 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:20:15.951756 31614 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:20:15.952656 31458 server_base.cc:1061] running on GCE node
I20260812 06:20:15.952888 31458 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:15.952932 31458 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:20:15.952950 31458 hybrid_clock.cc:648] HybridClock initialized: now 1786515615952950 us; error 0 us; skew 500 ppm
I20260812 06:20:15.954207 31458 webserver.cc:533] Webserver started at http://127.30.184.129:35643/ using document root <none> and password file <none>
I20260812 06:20:15.954459 31458 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:15.954560 31458 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:15.954667 31458 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:15.955135 31458 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/instance:
uuid: "6613ea25cf2543bda7559aee10b18c73"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-h6n0"
I20260812 06:20:15.956830 31458 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:15.957967 31623 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:20:15.958287 31458 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:15.958420 31458 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root
uuid: "6613ea25cf2543bda7559aee10b18c73"
format_stamp: "Formatted at 2026-08-12 06:20:15 on dist-test-slave-h6n0"
I20260812 06:20:15.958508 31458 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-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:20:15.972083 31458 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:15.972625 31458 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:15.973158 31458 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:15.974249 31458 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:15.974342 31458 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.974418 31458 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:15.974467 31458 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:15.982370 31458 rpc_server.cc:307] RPC server started. Bound to: 127.30.184.129:38419
I20260812 06:20:15.982431 31751 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.184.129:38419 every 8 connection(s)
I20260812 06:20:15.994626 31752 heartbeater.cc:344] Connected to a master server at 127.30.184.190:38505
I20260812 06:20:15.994935 31752 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:15.995458 31752 heartbeater.cc:507] Master 127.30.184.190:38505 requested a full tablet report, sending...
I20260812 06:20:15.997390 31508 ts_manager.cc:194] Registered new tserver with Master: 6613ea25cf2543bda7559aee10b18c73 (127.30.184.129:38419)
I20260812 06:20:15.997713 31458 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01459355s
I20260812 06:20:15.998991 31508 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56142
I20260812 06:20:16.008399 31508 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56154:
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:20:16.023831 31676 tablet_service.cc:1511] Processing CreateTablet for tablet 3277aca449d94e3f9aa463c88991f973 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1c105e1de0ba4386a41f3cacdf770770]), partition=
I20260812 06:20:16.024312 31676 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3277aca449d94e3f9aa463c88991f973. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:16.026665 31767 tablet_bootstrap.cc:492] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Bootstrap starting.
I20260812 06:20:16.027839 31767 tablet_bootstrap.cc:654] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:16.029052 31767 tablet_bootstrap.cc:492] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: No bootstrap required, opened a new log
I20260812 06:20:16.029143 31767 ts_tablet_manager.cc:1403] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:16.029878 31767 raft_consensus.cc:359] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6613ea25cf2543bda7559aee10b18c73" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 38419 } }
I20260812 06:20:16.029987 31767 raft_consensus.cc:385] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:16.030014 31767 raft_consensus.cc:740] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6613ea25cf2543bda7559aee10b18c73, State: Initialized, Role: FOLLOWER
I20260812 06:20:16.030215 31767 consensus_queue.cc:260] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [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: "6613ea25cf2543bda7559aee10b18c73" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 38419 } }
I20260812 06:20:16.030292 31767 raft_consensus.cc:399] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:16.030360 31767 raft_consensus.cc:493] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:16.030426 31767 raft_consensus.cc:3060] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:16.031495 31767 raft_consensus.cc:515] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6613ea25cf2543bda7559aee10b18c73" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 38419 } }
I20260812 06:20:16.031744 31767 leader_election.cc:304] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [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: 6613ea25cf2543bda7559aee10b18c73; no voters: 
I20260812 06:20:16.032048 31767 leader_election.cc:290] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:16.032169 31773 raft_consensus.cc:2804] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:16.032476 31767 ts_tablet_manager.cc:1434] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:16.032461 31773 raft_consensus.cc:697] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 1 LEADER]: Becoming Leader. State: Replica: 6613ea25cf2543bda7559aee10b18c73, State: Running, Role: LEADER
I20260812 06:20:16.032667 31773 consensus_queue.cc:237] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [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: "6613ea25cf2543bda7559aee10b18c73" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 38419 } }
I20260812 06:20:16.032820 31752 heartbeater.cc:499] Master 127.30.184.190:38505 was elected leader, sending a full tablet report...
I20260812 06:20:16.036348 31508 catalog_manager.cc:5719] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6613ea25cf2543bda7559aee10b18c73 (127.30.184.129). New cstate: current_term: 1 leader_uuid: "6613ea25cf2543bda7559aee10b18c73" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6613ea25cf2543bda7559aee10b18c73" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 38419 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:16.106971 31458 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.022s	sys 0.008s
I20260812 06:20:16.233942 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushMRSOp(3277aca449d94e3f9aa463c88991f973): perf score=15.086190
I20260812 06:20:16.417128 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushMRSOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.183s	user 0.139s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":233,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":808,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45454,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":160,"threads_started":1,"update_count":1500}
I20260812 06:20:16.418411 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling LogGCOp(3277aca449d94e3f9aa463c88991f973): free 8725963 bytes of WAL
I20260812 06:20:16.419073 31635 log_reader.cc:385] T 3277aca449d94e3f9aa463c88991f973: removed 1 log segments from log reader
I20260812 06:20:16.419178 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000001 (ops 1-6)
I20260812 06:20:16.422236 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: LogGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:16.422674 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973): 12308959 bytes on disk
I20260812 06:20:16.423352 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.423787 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:16.442987 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.443466 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:16.461059 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.461828 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:16.645134 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.183s	user 0.140s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733842,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":972,"lbm_read_time_us":12583,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32319,"lbm_writes_lt_1ms":543,"mutex_wait_us":106,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":362,"threads_started":5,"update_count":2500}
I20260812 06:20:16.645686 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:16.704775 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.059s	user 0.020s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20671,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.705611 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:16.718801 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.719520 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:16.853904 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.134s	user 0.106s	sys 0.028s 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":560,"lbm_read_time_us":10089,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27363,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74880,"update_count":2000}
I20260812 06:20:16.854511 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:16.908301 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.054s	user 0.027s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.908812 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:16.922101 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.922744 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:17.058913 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.136s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":10898,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26502,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:20:17.059458 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:17.127260 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.068s	user 0.023s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24439,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.127786 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.139286 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.139787 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:17.297856 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.158s	user 0.104s	sys 0.054s 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":163,"lbm_read_time_us":11550,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26127,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:17.298667 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:17.355273 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.056s	user 0.036s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20544,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.355748 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.369194 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.369724 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:17.502825 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.133s	user 0.113s	sys 0.020s 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":968,"lbm_read_time_us":7823,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27342,"lbm_writes_lt_1ms":443,"mutex_wait_us":9,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:17.503509 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:17.548429 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.045s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18587,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.548884 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.563968 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.564617 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:17.716813 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.152s	user 0.113s	sys 0.027s 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":519,"lbm_read_time_us":8520,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27090,"lbm_writes_lt_1ms":443,"mutex_wait_us":229,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.717583 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=7.149875
I20260812 06:20:17.744160 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.026s	user 0.020s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10818,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:17.744860 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.759786 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5831,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.760313 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushMRSOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:17.811121 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushMRSOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.051s	user 0.048s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1201,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2326,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:17.812080 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling LogGCOp(3277aca449d94e3f9aa463c88991f973): free 124257229 bytes of WAL
I20260812 06:20:17.812351 31635 log_reader.cc:385] T 3277aca449d94e3f9aa463c88991f973: removed 12 log segments from log reader
I20260812 06:20:17.812408 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000002 (ops 7-11)
I20260812 06:20:17.812448 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000003 (ops 12-16)
I20260812 06:20:17.812546 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000004 (ops 17-21)
I20260812 06:20:17.812587 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000005 (ops 22-26)
I20260812 06:20:17.812649 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000006 (ops 27-30)
I20260812 06:20:17.812693 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000007 (ops 31-35)
I20260812 06:20:17.812729 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000008 (ops 36-40)
I20260812 06:20:17.812793 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000009 (ops 41-45)
I20260812 06:20:17.812841 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000010 (ops 46-50)
I20260812 06:20:17.812892 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000011 (ops 51-55)
I20260812 06:20:17.812932 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000012 (ops 56-60)
I20260812 06:20:17.812958 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000013 (ops 61-65)
I20260812 06:20:17.846817 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: LogGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:20:17.847266 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973): 447 bytes on disk
I20260812 06:20:17.847729 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:17.848368 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.868019 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.868486 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:17.884428 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.885021 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:18.081053 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.196s	user 0.143s	sys 0.051s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24733952,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":526,"lbm_read_time_us":15176,"lbm_reads_lt_1ms":574,"lbm_write_time_us":34890,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23680,"thread_start_us":105,"threads_started":1,"update_count":2500}
I20260812 06:20:18.082175 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:18.136248 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.054s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21160,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:20:18.136859 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:18.153841 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.154762 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:18.326880 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.172s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":780,"lbm_read_time_us":10649,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33594,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:20:18.327374 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=12.110812
I20260812 06:20:18.385900 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.058s	user 0.034s	sys 0.021s Metrics: {"bytes_written":13661282,"delete_count":0,"lbm_write_time_us":25504,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1665}
I20260812 06:20:18.386512 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=1.196750
I20260812 06:20:18.405995 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.019s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3159084,"delete_count":0,"lbm_write_time_us":3930,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:20:18.406476 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:18.421018 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5343,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.421540 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:18.617190 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.195s	user 0.121s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":621,"lbm_read_time_us":13773,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34342,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:20:18.617996 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:18.682667 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.064s	user 0.038s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":30264,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.683128 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:18.694805 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.695271 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:18.884357 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.189s	user 0.110s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":12799,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36045,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:18.884934 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:18.952400 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.067s	user 0.026s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26191,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.953011 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:18.969909 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.970647 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:19.164785 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.194s	user 0.110s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":883,"lbm_read_time_us":14005,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28248,"lbm_writes_lt_1ms":543,"mutex_wait_us":316,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:19.165524 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:19.238021 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.072s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.238732 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:19.258492 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.020s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":8106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.259128 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:19.433617 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.174s	user 0.121s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":469,"lbm_read_time_us":12538,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27999,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:19.434376 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:19.486289 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.052s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22631,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.486833 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:19.498946 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.499660 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushMRSOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:19.538240 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushMRSOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.038s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1213,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1725,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:19.539124 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling LogGCOp(3277aca449d94e3f9aa463c88991f973): free 124710305 bytes of WAL
I20260812 06:20:19.539381 31635 log_reader.cc:385] T 3277aca449d94e3f9aa463c88991f973: removed 12 log segments from log reader
I20260812 06:20:19.539456 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000014 (ops 66-70)
I20260812 06:20:19.539556 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000015 (ops 71-75)
I20260812 06:20:19.539616 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000016 (ops 76-80)
I20260812 06:20:19.539656 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000017 (ops 81-85)
I20260812 06:20:19.539693 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000018 (ops 86-90)
I20260812 06:20:19.539729 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000019 (ops 91-95)
I20260812 06:20:19.539767 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000020 (ops 96-100)
I20260812 06:20:19.539804 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000021 (ops 101-105)
I20260812 06:20:19.539840 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000022 (ops 106-110)
I20260812 06:20:19.539877 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000023 (ops 111-115)
I20260812 06:20:19.539914 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000024 (ops 116-120)
I20260812 06:20:19.539958 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000025 (ops 121-125)
I20260812 06:20:19.568876 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: LogGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:19.569398 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973): 492 bytes on disk
I20260812 06:20:19.570034 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973) 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:20:19.570725 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=3.181125
I20260812 06:20:19.588346 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.017s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":113,"mutex_wait_us":48,"reinsert_count":0,"update_count":550}
I20260812 06:20:19.588763 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling LogGCOp(3277aca449d94e3f9aa463c88991f973): free 12017940 bytes of WAL
I20260812 06:20:19.588954 31635 log_reader.cc:385] T 3277aca449d94e3f9aa463c88991f973: removed 1 log segments from log reader
I20260812 06:20:19.588996 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000026 (ops 126-130)
I20260812 06:20:19.591897 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: LogGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:19.592258 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:19.602952 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4117,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.603361 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:19.834817 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.231s	user 0.151s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":955,"lbm_read_time_us":16352,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38216,"lbm_writes_lt_1ms":743,"mutex_wait_us":124,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:20:19.835749 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:19.890659 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.055s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:19.891258 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:19.908885 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.909405 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:20.100230 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.191s	user 0.111s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":572,"lbm_read_time_us":12316,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32468,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:20.100826 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:20.164778 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.064s	user 0.025s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.165390 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:20.177220 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.177721 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:20.374231 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.196s	user 0.129s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":14616,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33835,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32640,"update_count":2500}
I20260812 06:20:20.374948 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=11.118625
I20260812 06:20:20.412601 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15705,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.413436 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:20.435734 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.022s	user 0.008s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7024,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.436498 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:20.603117 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.166s	user 0.101s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":385,"lbm_read_time_us":11297,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27175,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.603816 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:20.658759 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.053s	user 0.010s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24647,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.659345 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:20.672891 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.673436 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:20.835561 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.162s	user 0.131s	sys 0.022s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1075,"lbm_read_time_us":9623,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35581,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:20:20.836278 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=11.118625
I20260812 06:20:20.868845 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.032s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14569,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.869622 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:20.886369 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6047,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.886897 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:21.021811 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.135s	user 0.110s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":7971,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29608,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:21.022718 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=10.126437
I20260812 06:20:21.072729 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.050s	user 0.035s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18614,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.073532 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:21.086112 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.086946 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushMRSOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:21.117179 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushMRSOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.030s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":335,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1790,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:21.118300 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling LogGCOp(3277aca449d94e3f9aa463c88991f973): free 108535684 bytes of WAL
I20260812 06:20:21.118718 31635 log_reader.cc:385] T 3277aca449d94e3f9aa463c88991f973: removed 11 log segments from log reader
I20260812 06:20:21.118808 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000027 (ops 131-135)
I20260812 06:20:21.118875 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000028 (ops 136-140)
I20260812 06:20:21.118989 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000029 (ops 141-144)
I20260812 06:20:21.119040 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000030 (ops 145-149)
I20260812 06:20:21.119086 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000031 (ops 150-154)
I20260812 06:20:21.119122 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000032 (ops 155-159)
I20260812 06:20:21.119166 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000033 (ops 160-164)
I20260812 06:20:21.119210 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000034 (ops 165-169)
I20260812 06:20:21.119261 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000035 (ops 170-174)
I20260812 06:20:21.119302 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000036 (ops 175-178)
I20260812 06:20:21.119346 31635 log.cc:1079] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/3277aca449d94e3f9aa463c88991f973/wal-000000037 (ops 179-183)
I20260812 06:20:21.148452 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: LogGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:21.148958 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=3.181125
I20260812 06:20:21.174225 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.025s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":8579,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:21.174856 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973): 461 bytes on disk
I20260812 06:20:21.175305 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: UndoDeltaBlockGCOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:20:21.175905 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:21.191601 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6311,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.192127 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:21.380084 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.188s	user 0.155s	sys 0.030s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836362,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":541,"lbm_read_time_us":14700,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40263,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:20:21.380977 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=14.095187
I20260812 06:20:21.447635 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.066s	user 0.029s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":30418,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.448684 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973): perf score=2.188937
I20260812 06:20:21.471452 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: FlushDeltaMemStoresOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.022s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.472052 31753 maintenance_manager.cc:419] P 6613ea25cf2543bda7559aee10b18c73: Scheduling MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973): perf score=1.000000
I20260812 06:20:21.493567 31458 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.386s	user 2.046s	sys 0.155s
I20260812 06:20:21.558825 31458 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.004s	sys 0.000s
I20260812 06:20:21.559525 31458 tablet_server.cc:179] TabletServer@127.30.184.129:0 shutting down...
I20260812 06:20:21.624672 31635 maintenance_manager.cc:643] P 6613ea25cf2543bda7559aee10b18c73: MajorDeltaCompactionOp(3277aca449d94e3f9aa463c88991f973) complete. Timing: real 0.152s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":13892,"lbm_reads_lt_1ms":560,"lbm_write_time_us":30249,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":64128,"update_count":2500}
I20260812 06:20:21.625581 31458 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:21.626041 31458 tablet_replica.cc:333] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73: stopping tablet replica
I20260812 06:20:21.626300 31458 raft_consensus.cc:2243] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.626641 31458 raft_consensus.cc:2272] T 3277aca449d94e3f9aa463c88991f973 P 6613ea25cf2543bda7559aee10b18c73 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.654484 31458 tablet_server.cc:196] TabletServer@127.30.184.129:0 shutdown complete.
I20260812 06:20:21.672024 31458 master.cc:562] Master@127.30.184.190:38505 shutting down...
I20260812 06:20:21.677677 31458 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:21.677981 31458 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:21.678081 31458 tablet_replica.cc:333] T 00000000000000000000000000000000 P 026768a4ad9742659963b8477f753cca: stopping tablet replica
I20260812 06:20:21.691859 31458 master.cc:584] Master@127.30.184.190:38505 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5985 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:21.790386 31458 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.184.190:43255
I20260812 06:20:21.790830 31458 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.793004 31806 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:20:21.793011 31804 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:20:21.793154 31458 server_base.cc:1061] running on GCE node
W20260812 06:20:21.793228 31808 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:20:21.793473 31458 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.793529 31458 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:20:21.793556 31458 hybrid_clock.cc:648] HybridClock initialized: now 1786515621793555 us; error 0 us; skew 500 ppm
I20260812 06:20:21.794442 31458 webserver.cc:533] Webserver started at http://127.30.184.190:43759/ using document root <none> and password file <none>
I20260812 06:20:21.794667 31458 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.794749 31458 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.794874 31458 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.795301 31458 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/master-0-root/instance:
uuid: "a40becc4a8314885aa518b670feceac3"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-h6n0"
I20260812 06:20:21.797143 31458 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.798971 31819 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:20:21.799393 31458 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:21.799520 31458 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/master-0-root
uuid: "a40becc4a8314885aa518b670feceac3"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-h6n0"
I20260812 06:20:21.799625 31458 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-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:20:21.814690 31458 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.815128 31458 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.820155 31458 rpc_server.cc:307] RPC server started. Bound to: 127.30.184.190:43255
I20260812 06:20:21.824469 31926 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.184.190:43255 every 8 connection(s)
I20260812 06:20:21.827191 31927 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:20:21.831543 31927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3: Bootstrap starting.
I20260812 06:20:21.832320 31927 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.833559 31927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3: No bootstrap required, opened a new log
I20260812 06:20:21.833966 31927 raft_consensus.cc:359] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40becc4a8314885aa518b670feceac3" member_type: VOTER }
I20260812 06:20:21.834062 31927 raft_consensus.cc:385] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.834090 31927 raft_consensus.cc:740] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a40becc4a8314885aa518b670feceac3, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.834208 31927 consensus_queue.cc:260] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [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: "a40becc4a8314885aa518b670feceac3" member_type: VOTER }
I20260812 06:20:21.834319 31927 raft_consensus.cc:399] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.834373 31927 raft_consensus.cc:493] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.834463 31927 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.835271 31927 raft_consensus.cc:515] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40becc4a8314885aa518b670feceac3" member_type: VOTER }
I20260812 06:20:21.835438 31927 leader_election.cc:304] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [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: a40becc4a8314885aa518b670feceac3; no voters: 
I20260812 06:20:21.835667 31927 leader_election.cc:290] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.835809 31931 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.836084 31931 raft_consensus.cc:697] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 1 LEADER]: Becoming Leader. State: Replica: a40becc4a8314885aa518b670feceac3, State: Running, Role: LEADER
I20260812 06:20:21.836203 31927 sys_catalog.cc:565] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:21.836275 31931 consensus_queue.cc:237] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [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: "a40becc4a8314885aa518b670feceac3" member_type: VOTER }
I20260812 06:20:21.836794 31932 sys_catalog.cc:455] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a40becc4a8314885aa518b670feceac3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40becc4a8314885aa518b670feceac3" member_type: VOTER } }
I20260812 06:20:21.836822 31933 sys_catalog.cc:455] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a40becc4a8314885aa518b670feceac3. Latest consensus state: current_term: 1 leader_uuid: "a40becc4a8314885aa518b670feceac3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a40becc4a8314885aa518b670feceac3" member_type: VOTER } }
I20260812 06:20:21.836973 31933 sys_catalog.cc:458] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.837239 31932 sys_catalog.cc:458] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.837602 31941 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:21.838328 31941 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:21.838562 31458 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:21.840452 31941 catalog_manager.cc:1383] Generated new cluster ID: bbdf3a5412e7471abf681b15ed06360b
I20260812 06:20:21.840523 31941 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:21.863690 31941 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:21.864317 31941 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:21.871340 31941 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3: Generated new TSK 0
I20260812 06:20:21.871523 31941 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:21.903582 31458 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.905891 31959 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:20:21.906054 31961 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:20:21.906138 31956 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:20:21.906320 31458 server_base.cc:1061] running on GCE node
I20260812 06:20:21.906649 31458 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.906702 31458 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:20:21.906719 31458 hybrid_clock.cc:648] HybridClock initialized: now 1786515621906720 us; error 0 us; skew 500 ppm
I20260812 06:20:21.907757 31458 webserver.cc:533] Webserver started at http://127.30.184.129:42141/ using document root <none> and password file <none>
I20260812 06:20:21.908074 31458 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.908135 31458 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.908227 31458 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.908701 31458 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/instance:
uuid: "bb7a07d0ae094ac3a2190f6b362c3773"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-h6n0"
I20260812 06:20:21.910662 31458 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.911868 31968 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:20:21.912279 31458 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.912385 31458 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root
uuid: "bb7a07d0ae094ac3a2190f6b362c3773"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-h6n0"
I20260812 06:20:21.912482 31458 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-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:20:21.925591 31458 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.925985 31458 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.926327 31458 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:21.926864 31458 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:21.926903 31458 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.926935 31458 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:21.926949 31458 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.931596 31458 rpc_server.cc:307] RPC server started. Bound to: 127.30.184.129:40325
I20260812 06:20:21.932296 32075 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.184.129:40325 every 8 connection(s)
I20260812 06:20:21.937373 32076 heartbeater.cc:344] Connected to a master server at 127.30.184.190:43255
I20260812 06:20:21.937491 32076 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:21.937675 32076 heartbeater.cc:507] Master 127.30.184.190:43255 requested a full tablet report, sending...
I20260812 06:20:21.938510 31848 ts_manager.cc:194] Registered new tserver with Master: bb7a07d0ae094ac3a2190f6b362c3773 (127.30.184.129:40325)
I20260812 06:20:21.939097 31458 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006721826s
I20260812 06:20:21.939692 31848 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38842
I20260812 06:20:21.947656 31848 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38848:
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:20:21.959280 32019 tablet_service.cc:1511] Processing CreateTablet for tablet 27f9a8ee7db24987b342ec2f2a5b15e1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2e5087c7732f4028a8d29aed72984145]), partition=
I20260812 06:20:21.959642 32019 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 27f9a8ee7db24987b342ec2f2a5b15e1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:21.961686 32099 tablet_bootstrap.cc:492] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Bootstrap starting.
I20260812 06:20:21.962745 32099 tablet_bootstrap.cc:654] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.963801 32099 tablet_bootstrap.cc:492] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: No bootstrap required, opened a new log
I20260812 06:20:21.963907 32099 ts_tablet_manager.cc:1403] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.964274 32099 raft_consensus.cc:359] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7a07d0ae094ac3a2190f6b362c3773" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 40325 } }
I20260812 06:20:21.964370 32099 raft_consensus.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.964394 32099 raft_consensus.cc:740] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb7a07d0ae094ac3a2190f6b362c3773, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.964596 32099 consensus_queue.cc:260] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [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: "bb7a07d0ae094ac3a2190f6b362c3773" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 40325 } }
I20260812 06:20:21.964722 32099 raft_consensus.cc:399] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.964776 32099 raft_consensus.cc:493] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.964846 32099 raft_consensus.cc:3060] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.965742 32099 raft_consensus.cc:515] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7a07d0ae094ac3a2190f6b362c3773" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 40325 } }
I20260812 06:20:21.965880 32099 leader_election.cc:304] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [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: bb7a07d0ae094ac3a2190f6b362c3773; no voters: 
I20260812 06:20:21.966034 32099 leader_election.cc:290] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.966187 32101 raft_consensus.cc:2804] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.966429 32101 raft_consensus.cc:697] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 1 LEADER]: Becoming Leader. State: Replica: bb7a07d0ae094ac3a2190f6b362c3773, State: Running, Role: LEADER
I20260812 06:20:21.966415 32076 heartbeater.cc:499] Master 127.30.184.190:43255 was elected leader, sending a full tablet report...
I20260812 06:20:21.966418 32099 ts_tablet_manager.cc:1434] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:21.966698 32101 consensus_queue.cc:237] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [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: "bb7a07d0ae094ac3a2190f6b362c3773" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 40325 } }
I20260812 06:20:21.968083 31848 catalog_manager.cc:5719] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 reported cstate change: term changed from 0 to 1, leader changed from <none> to bb7a07d0ae094ac3a2190f6b362c3773 (127.30.184.129). New cstate: current_term: 1 leader_uuid: "bb7a07d0ae094ac3a2190f6b362c3773" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb7a07d0ae094ac3a2190f6b362c3773" member_type: VOTER last_known_addr { host: "127.30.184.129" port: 40325 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.032176 31458 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.016s	sys 0.009s
I20260812 06:20:22.182914 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=19.054940
I20260812 06:20:22.351455 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.168s	user 0.118s	sys 0.046s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":822,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44528,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:22.352144 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): free 20290830 bytes of WAL
I20260812 06:20:22.352438 31977 log_reader.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1: removed 2 log segments from log reader
I20260812 06:20:22.352547 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000001 (ops 1-6)
I20260812 06:20:22.352624 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000002 (ops 7-10)
I20260812 06:20:22.356709 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:22.357138 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:22.374729 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.375308 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): 16411393 bytes on disk
I20260812 06:20:22.375777 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) 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:20:22.376327 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:22.534276 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.158s	user 0.105s	sys 0.044s 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":583,"lbm_read_time_us":10700,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25534,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":361,"threads_started":5,"update_count":2000}
I20260812 06:20:22.535006 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:22.596865 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.062s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24286,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.597398 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:22.610195 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.610750 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:22.798750 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.188s	user 0.121s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3834,"lbm_read_time_us":12796,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30484,"lbm_writes_lt_1ms":543,"mutex_wait_us":2996,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:20:22.799448 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:22.861275 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.062s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.861835 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:22.873172 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.873678 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:23.064869 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.191s	user 0.135s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":813,"lbm_read_time_us":14411,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31040,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:20:23.069164 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=10.126437
I20260812 06:20:23.113062 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19286,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.113935 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:23.144210 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.030s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":500}
I20260812 06:20:23.144843 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:23.159677 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6133,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.160148 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:23.361395 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.201s	user 0.122s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":490,"lbm_read_time_us":13263,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34963,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:20:23.362139 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:23.417738 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.055s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21202,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.418196 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:23.440205 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.022s	user 0.006s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.440855 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:23.641952 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.201s	user 0.132s	sys 0.068s 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":154,"lbm_read_time_us":12082,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33733,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:20:23.642676 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:23.697402 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.055s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24172,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.698021 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:23.712205 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.712738 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:23.753432 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.041s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1705,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:23.754066 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): free 120553374 bytes of WAL
I20260812 06:20:23.754282 31977 log_reader.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1: removed 12 log segments from log reader
I20260812 06:20:23.754324 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000003 (ops 11-15)
I20260812 06:20:23.754354 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000004 (ops 16-20)
I20260812 06:20:23.754423 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000005 (ops 21-25)
I20260812 06:20:23.754468 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000006 (ops 26-30)
I20260812 06:20:23.754510 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000007 (ops 31-35)
I20260812 06:20:23.754603 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000008 (ops 36-40)
I20260812 06:20:23.754637 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000009 (ops 41-44)
I20260812 06:20:23.754673 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000010 (ops 45-49)
I20260812 06:20:23.754714 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000011 (ops 50-54)
I20260812 06:20:23.754752 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000012 (ops 55-58)
I20260812 06:20:23.754791 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000013 (ops 59-63)
I20260812 06:20:23.754840 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000014 (ops 64-68)
I20260812 06:20:23.780638 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:23.781054 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=3.181125
I20260812 06:20:23.802992 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.022s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7232,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.803406 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): 463 bytes on disk
I20260812 06:20:23.803782 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.804294 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:23.813920 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3737,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.814276 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:24.086350 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.272s	user 0.181s	sys 0.074s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":641,"dirs.run_cpu_time_us":854,"dirs.run_wall_time_us":3245,"lbm_read_time_us":17208,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43277,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":261,"threads_started":1,"update_count":3500}
I20260812 06:20:24.087076 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=18.063937
I20260812 06:20:24.156569 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.069s	user 0.025s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"mutex_wait_us":118,"reinsert_count":0,"update_count":2500}
I20260812 06:20:24.157155 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:24.167244 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.167644 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:24.385066 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.217s	user 0.129s	sys 0.087s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1451,"lbm_read_time_us":15136,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38354,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:20:24.387157 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:24.433223 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.046s	user 0.037s	sys 0.006s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20249,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.433935 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:24.449626 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.450254 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:24.634696 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.184s	user 0.119s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":11237,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33592,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:20:24.635273 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:24.697752 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.062s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17832,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.698326 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:24.711267 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.711869 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:24.906647 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.195s	user 0.135s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":498,"lbm_read_time_us":13999,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33818,"lbm_writes_lt_1ms":543,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:20:24.907338 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:24.975778 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.068s	user 0.048s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24240,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.976492 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:24.989197 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.989851 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:25.202375 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.212s	user 0.143s	sys 0.059s 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":505,"lbm_read_time_us":15060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35128,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:20:25.203181 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:25.259296 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.056s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.259807 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:25.279639 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.020s	user 0.008s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.280184 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:25.326933 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.047s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":333,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2109,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:25.327878 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): free 112692317 bytes of WAL
I20260812 06:20:25.328356 31977 log_reader.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1: removed 11 log segments from log reader
I20260812 06:20:25.328583 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000015 (ops 69-73)
I20260812 06:20:25.328701 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000016 (ops 74-78)
I20260812 06:20:25.328747 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000017 (ops 79-83)
I20260812 06:20:25.328794 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000018 (ops 84-88)
I20260812 06:20:25.328832 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000019 (ops 89-93)
I20260812 06:20:25.328873 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000020 (ops 94-98)
I20260812 06:20:25.328912 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000021 (ops 99-103)
I20260812 06:20:25.328953 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000022 (ops 104-108)
I20260812 06:20:25.328994 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000023 (ops 109-113)
I20260812 06:20:25.329032 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000024 (ops 114-118)
I20260812 06:20:25.329066 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000025 (ops 119-123)
I20260812 06:20:25.354969 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:25.355516 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): 447 bytes on disk
I20260812 06:20:25.356094 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.356751 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:25.383872 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.384409 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:25.399379 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.399966 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:25.680143 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.280s	user 0.183s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1374,"lbm_read_time_us":17774,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46449,"lbm_writes_lt_1ms":743,"mutex_wait_us":350,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:20:25.681058 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=18.063937
I20260812 06:20:25.763255 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.082s	user 0.031s	sys 0.036s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":31226,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:25.763805 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:25.775746 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.776414 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:26.035794 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.259s	user 0.156s	sys 0.099s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":17645,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41564,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:20:26.036499 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=18.063937
I20260812 06:20:26.107622 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.071s	user 0.038s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30769,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.108096 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:26.120072 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.120553 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:26.357172 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.236s	user 0.181s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":16211,"lbm_reads_lt_1ms":672,"lbm_write_time_us":42883,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:20:26.357786 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:26.426044 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.068s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27639,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.426587 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:26.438282 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.438838 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:26.630172 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.191s	user 0.138s	sys 0.053s 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":249,"lbm_read_time_us":15336,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31165,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":2500}
I20260812 06:20:26.631148 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:26.696372 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.065s	user 0.041s	sys 0.014s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.697140 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:26.710723 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.711803 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:26.911592 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.200s	user 0.127s	sys 0.072s 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":1129,"lbm_read_time_us":15766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33716,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:20:26.912154 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=14.095187
I20260812 06:20:26.986030 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.074s	user 0.039s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:26.986675 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:27.000921 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.001665 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:27.070451 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushMRSOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.069s	user 0.039s	sys 0.003s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1487,"drs_written":1,"lbm_read_time_us":157,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":19840}
I20260812 06:20:27.071342 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): free 120553613 bytes of WAL
I20260812 06:20:27.071770 31977 log_reader.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1: removed 12 log segments from log reader
I20260812 06:20:27.071887 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000026 (ops 124-128)
I20260812 06:20:27.071957 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000027 (ops 129-133)
I20260812 06:20:27.072003 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000028 (ops 134-138)
I20260812 06:20:27.072045 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000029 (ops 139-143)
I20260812 06:20:27.072084 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000030 (ops 144-148)
I20260812 06:20:27.072117 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000031 (ops 149-153)
I20260812 06:20:27.072155 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000032 (ops 154-158)
I20260812 06:20:27.072193 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000033 (ops 159-162)
I20260812 06:20:27.072219 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000034 (ops 163-167)
I20260812 06:20:27.072247 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000035 (ops 168-172)
I20260812 06:20:27.072278 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000036 (ops 173-176)
I20260812 06:20:27.072482 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000037 (ops 177-181)
I20260812 06:20:27.101661 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:27.102253 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): 473 bytes on disk
I20260812 06:20:27.103087 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: UndoDeltaBlockGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.104933 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=7.149875
I20260812 06:20:27.136544 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.031s	user 0.017s	sys 0.012s Metrics: {"bytes_written":8410199,"delete_count":0,"lbm_write_time_us":13793,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1025}
I20260812 06:20:27.137038 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1): free 12018006 bytes of WAL
I20260812 06:20:27.137270 31977 log_reader.cc:385] T 27f9a8ee7db24987b342ec2f2a5b15e1: removed 1 log segments from log reader
I20260812 06:20:27.137344 31977 log.cc:1079] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: Deleting log segment in path: /tmp/dist-test-taskTxL5FL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515615794121-31458-0/minicluster-data/ts-0-root/wals/27f9a8ee7db24987b342ec2f2a5b15e1/wal-000000038 (ops 182-186)
I20260812 06:20:27.140022 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: LogGCOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:27.140339 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:27.154266 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":5189,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:20:27.154834 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:27.426126 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.271s	user 0.178s	sys 0.080s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082159,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":244,"lbm_read_time_us":19819,"lbm_reads_lt_1ms":874,"lbm_write_time_us":46073,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":347,"threads_started":6,"update_count":4000}
I20260812 06:20:27.427076 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=22.032687
I20260812 06:20:27.480062 31458 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.448s	user 2.015s	sys 0.208s
I20260812 06:20:27.492664 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.065s	user 0.044s	sys 0.020s Metrics: {"bytes_written":24614721,"delete_count":0,"lbm_write_time_us":31136,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:20:27.493189 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=2.188937
I20260812 06:20:27.509564 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: FlushDeltaMemStoresOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.510386 32077 maintenance_manager.cc:419] P bb7a07d0ae094ac3a2190f6b362c3773: Scheduling MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1): perf score=1.000000
I20260812 06:20:27.521526 31458 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.041s	user 0.001s	sys 0.000s
I20260812 06:20:27.522177 31458 tablet_server.cc:179] TabletServer@127.30.184.129:0 shutting down...
I20260812 06:20:27.697188 31977 maintenance_manager.cc:643] P bb7a07d0ae094ac3a2190f6b362c3773: MajorDeltaCompactionOp(27f9a8ee7db24987b342ec2f2a5b15e1) complete. Timing: real 0.187s	user 0.151s	sys 0.035s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":702,"cfile_cache_miss_bytes":28717118,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":702,"lbm_read_time_us":14007,"lbm_reads_lt_1ms":718,"lbm_write_time_us":39981,"lbm_writes_lt_1ms":743,"mutex_wait_us":258,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:20:27.697925 31458 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.698168 31458 tablet_replica.cc:333] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773: stopping tablet replica
I20260812 06:20:27.698294 31458 raft_consensus.cc:2243] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.698588 31458 raft_consensus.cc:2272] T 27f9a8ee7db24987b342ec2f2a5b15e1 P bb7a07d0ae094ac3a2190f6b362c3773 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.703131 31458 tablet_server.cc:196] TabletServer@127.30.184.129:0 shutdown complete.
I20260812 06:20:27.757472 31458 master.cc:562] Master@127.30.184.190:43255 shutting down...
I20260812 06:20:27.761994 31458 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.762212 31458 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.762296 31458 tablet_replica.cc:333] T 00000000000000000000000000000000 P a40becc4a8314885aa518b670feceac3: stopping tablet replica
I20260812 06:20:27.775243 31458 master.cc:584] Master@127.30.184.190:43255 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6075 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12062 ms total)

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