[==========] 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:17:38.899698 27096 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.118.62:34369
I20260812 06:17:38.900745 27096 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:17:38.901360 27096 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:38.908354 27104 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:17:38.908356 27103 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:17:38.908646 27106 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:17:38.908703 27096 server_base.cc:1061] running on GCE node
I20260812 06:17:38.909348 27096 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:38.909474 27096 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:17:38.909503 27096 hybrid_clock.cc:648] HybridClock initialized: now 1786515458909502 us; error 0 us; skew 500 ppm
I20260812 06:17:38.911444 27096 webserver.cc:533] Webserver started at http://127.26.118.62:35145/ using document root <none> and password file <none>
I20260812 06:17:38.912017 27096 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:38.912083 27096 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:38.912302 27096 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:38.914165 27096 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/master-0-root/instance:
uuid: "9bfc8cfe91c24c53968cfbea314bdbb8"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-pgkr"
I20260812 06:17:38.918118 27096 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.003s
I20260812 06:17:38.921031 27111 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:17:38.922324 27096 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:38.922443 27096 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/master-0-root
uuid: "9bfc8cfe91c24c53968cfbea314bdbb8"
format_stamp: "Formatted at 2026-08-12 06:17:38 on dist-test-slave-pgkr"
I20260812 06:17:38.922547 27096 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-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:17:38.937037 27096 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:38.937688 27096 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:17:38.937830 27096 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:38.946316 27096 rpc_server.cc:307] RPC server started. Bound to: 127.26.118.62:34369
I20260812 06:17:38.946404 27169 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.118.62:34369 every 8 connection(s)
I20260812 06:17:38.948800 27170 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:17:38.954473 27170 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: Bootstrap starting.
I20260812 06:17:38.956974 27170 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.957953 27170 log.cc:826] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:38.959975 27170 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: No bootstrap required, opened a new log
I20260812 06:17:38.962987 27170 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER }
I20260812 06:17:38.963179 27170 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.963258 27170 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9bfc8cfe91c24c53968cfbea314bdbb8, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.963955 27170 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [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: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER }
I20260812 06:17:38.964148 27170 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.964229 27170 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.964423 27170 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.965333 27170 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER }
I20260812 06:17:38.965818 27170 leader_election.cc:304] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [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: 9bfc8cfe91c24c53968cfbea314bdbb8; no voters: 
I20260812 06:17:38.966179 27170 leader_election.cc:290] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.966355 27173 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.966656 27173 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 1 LEADER]: Becoming Leader. State: Replica: 9bfc8cfe91c24c53968cfbea314bdbb8, State: Running, Role: LEADER
I20260812 06:17:38.967064 27173 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [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: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER }
I20260812 06:17:38.967315 27170 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:38.969018 27175 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9bfc8cfe91c24c53968cfbea314bdbb8. Latest consensus state: current_term: 1 leader_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER } }
I20260812 06:17:38.969054 27174 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9bfc8cfe91c24c53968cfbea314bdbb8" member_type: VOTER } }
I20260812 06:17:38.969172 27175 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.969172 27174 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:38.969628 27186 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:38.969667 27096 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:38.971918 27186 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:38.976466 27186 catalog_manager.cc:1383] Generated new cluster ID: 39d1b99d7382457b98aeaf5567152c9d
I20260812 06:17:38.976541 27186 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:39.001643 27186 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:39.002555 27186 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:39.013418 27186 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: Generated new TSK 0
I20260812 06:17:39.014286 27186 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:39.035197 27096 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:39.038453 27193 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:17:39.038479 27194 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:17:39.038475 27196 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:17:39.038735 27096 server_base.cc:1061] running on GCE node
I20260812 06:17:39.038913 27096 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:39.038951 27096 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:17:39.038973 27096 hybrid_clock.cc:648] HybridClock initialized: now 1786515459038973 us; error 0 us; skew 500 ppm
I20260812 06:17:39.040033 27096 webserver.cc:533] Webserver started at http://127.26.118.1:38929/ using document root <none> and password file <none>
I20260812 06:17:39.040208 27096 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:39.040267 27096 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:39.040350 27096 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:39.040804 27096 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/instance:
uuid: "978ef2c64c3a4c02822ed77dec02a07f"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-pgkr"
I20260812 06:17:39.042730 27096 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:39.043974 27203 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:17:39.044364 27096 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:39.044445 27096 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root
uuid: "978ef2c64c3a4c02822ed77dec02a07f"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-pgkr"
I20260812 06:17:39.044521 27096 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-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:17:39.065902 27096 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:39.066449 27096 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:39.067071 27096 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:39.068070 27096 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:39.068137 27096 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:39.068195 27096 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:39.068226 27096 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:39.076326 27096 rpc_server.cc:307] RPC server started. Bound to: 127.26.118.1:46363
I20260812 06:17:39.076398 27276 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.118.1:46363 every 8 connection(s)
I20260812 06:17:39.086575 27277 heartbeater.cc:344] Connected to a master server at 127.26.118.62:34369
I20260812 06:17:39.086902 27277 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:39.087419 27277 heartbeater.cc:507] Master 127.26.118.62:34369 requested a full tablet report, sending...
I20260812 06:17:39.089066 27129 ts_manager.cc:194] Registered new tserver with Master: 978ef2c64c3a4c02822ed77dec02a07f (127.26.118.1:46363)
I20260812 06:17:39.089277 27096 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012310671s
I20260812 06:17:39.090663 27129 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42030
I20260812 06:17:39.099313 27129 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42034:
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:17:39.114720 27237 tablet_service.cc:1511] Processing CreateTablet for tablet 5132d2ba7d7d4b1da610d4c72ebaa2d6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7a4707f9aed84b58b0cdd05fd5ec38c8]), partition=
I20260812 06:17:39.115232 27237 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5132d2ba7d7d4b1da610d4c72ebaa2d6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:39.118530 27291 tablet_bootstrap.cc:492] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Bootstrap starting.
I20260812 06:17:39.119664 27291 tablet_bootstrap.cc:654] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:39.120869 27291 tablet_bootstrap.cc:492] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: No bootstrap required, opened a new log
I20260812 06:17:39.121023 27291 ts_tablet_manager.cc:1403] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:39.121485 27291 raft_consensus.cc:359] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "978ef2c64c3a4c02822ed77dec02a07f" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 46363 } }
I20260812 06:17:39.121613 27291 raft_consensus.cc:385] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:39.121665 27291 raft_consensus.cc:740] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 978ef2c64c3a4c02822ed77dec02a07f, State: Initialized, Role: FOLLOWER
I20260812 06:17:39.121833 27291 consensus_queue.cc:260] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [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: "978ef2c64c3a4c02822ed77dec02a07f" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 46363 } }
I20260812 06:17:39.121948 27291 raft_consensus.cc:399] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:39.121997 27291 raft_consensus.cc:493] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:39.122051 27291 raft_consensus.cc:3060] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:39.122996 27291 raft_consensus.cc:515] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "978ef2c64c3a4c02822ed77dec02a07f" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 46363 } }
I20260812 06:17:39.123157 27291 leader_election.cc:304] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [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: 978ef2c64c3a4c02822ed77dec02a07f; no voters: 
I20260812 06:17:39.123430 27291 leader_election.cc:290] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:39.123526 27293 raft_consensus.cc:2804] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:39.123719 27293 raft_consensus.cc:697] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 1 LEADER]: Becoming Leader. State: Replica: 978ef2c64c3a4c02822ed77dec02a07f, State: Running, Role: LEADER
I20260812 06:17:39.123809 27291 ts_tablet_manager.cc:1434] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:17:39.123924 27293 consensus_queue.cc:237] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [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: "978ef2c64c3a4c02822ed77dec02a07f" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 46363 } }
I20260812 06:17:39.124128 27277 heartbeater.cc:499] Master 127.26.118.62:34369 was elected leader, sending a full tablet report...
I20260812 06:17:39.126718 27129 catalog_manager.cc:5719] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f reported cstate change: term changed from 0 to 1, leader changed from <none> to 978ef2c64c3a4c02822ed77dec02a07f (127.26.118.1). New cstate: current_term: 1 leader_uuid: "978ef2c64c3a4c02822ed77dec02a07f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "978ef2c64c3a4c02822ed77dec02a07f" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 46363 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:39.197556 27096 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.025s	sys 0.004s
I20260812 06:17:39.327832 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=15.086190
I20260812 06:17:39.483644 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.155s	user 0.115s	sys 0.028s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":214,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1036,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35056,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":135,"threads_started":1,"update_count":1450}
I20260812 06:17:39.484939 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): free 20743880 bytes of WAL
I20260812 06:17:39.485260 27209 log_reader.cc:385] T 5132d2ba7d7d4b1da610d4c72ebaa2d6: removed 2 log segments from log reader
I20260812 06:17:39.485332 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000001 (ops 1-6)
I20260812 06:17:39.485392 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000002 (ops 7-11)
I20260812 06:17:39.491317 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:39.491822 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): 12719216 bytes on disk
I20260812 06:17:39.492718 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":128,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.493257 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:39.511229 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.511786 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:39.656045 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.144s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2347,"lbm_read_time_us":9169,"lbm_reads_lt_1ms":450,"lbm_write_time_us":26315,"lbm_writes_lt_1ms":433,"mutex_wait_us":430,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":669,"threads_started":5,"update_count":1950}
I20260812 06:17:39.656864 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:39.733903 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.077s	user 0.038s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":27291,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:39.736109 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:39.807185 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.071s	user 0.050s	sys 0.020s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":31013,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.808254 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:40.098767 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.290s	user 0.222s	sys 0.067s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3154,"lbm_read_time_us":32043,"lbm_reads_lt_1ms":472,"lbm_write_time_us":51018,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":1021,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:40.100968 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:40.174700 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.073s	user 0.041s	sys 0.031s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":32886,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.175836 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:40.206156 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.030s	user 0.020s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.207280 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:40.466547 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.259s	user 0.194s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":19665,"lbm_reads_lt_1ms":472,"lbm_write_time_us":59751,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:17:40.470227 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:40.580961 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.110s	user 0.044s	sys 0.048s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":36429,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.582278 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:40.605860 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.023s	user 0.012s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.606405 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:40.784485 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.178s	user 0.139s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":856,"lbm_read_time_us":21999,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25545,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:40.785108 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:40.828430 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.043s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16380,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.828919 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:40.840898 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.841529 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:40.973311 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.132s	user 0.081s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":8401,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27736,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:40.973884 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:41.016459 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19800,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.017127 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:41.034462 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.035212 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:41.168043 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.133s	user 0.096s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":9979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26806,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:17:41.168967 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:41.211140 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.042s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19586,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.211637 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:41.223734 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.224406 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:41.372679 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.148s	user 0.096s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":12456,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27893,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.373389 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:41.425925 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.052s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17694,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.426434 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:41.437065 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.437598 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:41.480441 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.043s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":289,"dirs.run_wall_time_us":1373,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1500,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:41.481302 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): free 124710247 bytes of WAL
I20260812 06:17:41.481542 27209 log_reader.cc:385] T 5132d2ba7d7d4b1da610d4c72ebaa2d6: removed 12 log segments from log reader
I20260812 06:17:41.481586 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000003 (ops 12-16)
I20260812 06:17:41.481622 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000004 (ops 17-21)
I20260812 06:17:41.481688 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000005 (ops 22-26)
I20260812 06:17:41.481735 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000006 (ops 27-31)
I20260812 06:17:41.481781 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000007 (ops 32-36)
I20260812 06:17:41.481799 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000008 (ops 37-41)
I20260812 06:17:41.481854 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000009 (ops 42-46)
I20260812 06:17:41.481895 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000010 (ops 47-51)
I20260812 06:17:41.481935 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000011 (ops 52-56)
I20260812 06:17:41.481973 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000012 (ops 57-61)
I20260812 06:17:41.482012 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000013 (ops 62-66)
I20260812 06:17:41.482048 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000014 (ops 67-71)
I20260812 06:17:41.509407 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:41.509944 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): 483 bytes on disk
I20260812 06:17:41.510444 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.511119 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=3.181125
I20260812 06:17:41.534003 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.023s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7695,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:41.534440 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:41.544632 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:41.545154 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:41.751588 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.206s	user 0.142s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":833,"lbm_read_time_us":14479,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35572,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:17:41.752290 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:41.796187 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.044s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.796828 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:41.947023 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.150s	user 0.105s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2221,"lbm_read_time_us":12156,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23695,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:17:41.947844 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:41.982230 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14588,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.982868 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:41.999415 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.000147 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:42.121447 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.121s	user 0.093s	sys 0.027s 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":138,"lbm_read_time_us":8009,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22963,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:42.122112 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:42.160912 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.039s	user 0.015s	sys 0.022s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16420,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.161535 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.178244 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.178911 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:42.311165 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.132s	user 0.091s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":123,"lbm_read_time_us":7791,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29414,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:42.311959 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:42.362748 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.051s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19165,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.363394 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.379908 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.380548 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:42.516693 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.136s	user 0.125s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":10038,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28567,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:42.517410 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:42.567422 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.050s	user 0.008s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16917,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.568040 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.579535 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.580107 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:42.734191 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.154s	user 0.104s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":11509,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25276,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:42.734920 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=10.126437
I20260812 06:17:42.780081 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.045s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.780582 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.799319 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.799825 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:42.931051 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.131s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":7604,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25992,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:17:42.931802 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=11.118625
I20260812 06:17:42.975864 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.044s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17888,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:42.976362 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.987902 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.988377 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:42.998172 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3596,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.998710 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:43.032922 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":115,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2347,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:43.033685 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): free 133024445 bytes of WAL
I20260812 06:17:43.033916 27209 log_reader.cc:385] T 5132d2ba7d7d4b1da610d4c72ebaa2d6: removed 13 log segments from log reader
I20260812 06:17:43.033959 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000015 (ops 72-76)
I20260812 06:17:43.033989 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000016 (ops 77-80)
I20260812 06:17:43.034055 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000017 (ops 81-85)
I20260812 06:17:43.034106 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000018 (ops 86-90)
I20260812 06:17:43.034148 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000019 (ops 91-95)
I20260812 06:17:43.034210 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000020 (ops 96-100)
I20260812 06:17:43.034251 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000021 (ops 101-105)
I20260812 06:17:43.034296 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000022 (ops 106-110)
I20260812 06:17:43.034332 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000023 (ops 111-115)
I20260812 06:17:43.034369 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000024 (ops 116-120)
I20260812 06:17:43.034410 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000025 (ops 121-125)
I20260812 06:17:43.034451 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000026 (ops 126-130)
I20260812 06:17:43.034490 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000027 (ops 131-135)
I20260812 06:17:43.063088 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:43.063537 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): 482 bytes on disk
I20260812 06:17:43.064059 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.064594 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=3.181125
I20260812 06:17:43.081384 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4718029,"delete_count":0,"lbm_write_time_us":7166,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:17:43.081818 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:43.091763 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3457,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:17:43.092449 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:43.296574 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.204s	user 0.144s	sys 0.056s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1204,"dirs.run_cpu_time_us":456,"dirs.run_wall_time_us":2830,"lbm_read_time_us":14229,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41477,"lbm_writes_lt_1ms":743,"mutex_wait_us":24,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":3500}
I20260812 06:17:43.297605 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:43.345865 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.048s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21276,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.346592 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:43.363533 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.017s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4225734,"delete_count":0,"lbm_write_time_us":5301,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:17:43.364078 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:43.539157 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.175s	user 0.120s	sys 0.053s Metrics: {"cfile_cache_miss":535,"cfile_cache_miss_bytes":24897763,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2821,"lbm_read_time_us":13428,"lbm_reads_lt_1ms":567,"lbm_write_time_us":29027,"lbm_writes_lt_1ms":546,"mutex_wait_us":2128,"peak_mem_usage":63239005,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2515}
I20260812 06:17:43.539839 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:43.593531 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.054s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16286832,"delete_count":0,"lbm_write_time_us":27120,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":398,"reinsert_count":0,"update_count":1985}
I20260812 06:17:43.594125 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:43.611872 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.018s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.612457 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:43.785399 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.173s	user 0.115s	sys 0.051s Metrics: {"cfile_cache_miss":529,"cfile_cache_miss_bytes":24651619,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":359,"lbm_read_time_us":10981,"lbm_reads_lt_1ms":561,"lbm_write_time_us":29987,"lbm_writes_lt_1ms":540,"mutex_wait_us":64,"peak_mem_usage":61952411,"reinsert_count":0,"spinlock_wait_cycles":60032,"update_count":2485}
I20260812 06:17:43.785888 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:43.837299 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24138,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.837805 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:43.849712 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102662,"delete_count":0,"lbm_write_time_us":4655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.850183 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:44.013796 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.163s	user 0.128s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":10890,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35121,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.014446 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:44.065411 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.051s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23582,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.065944 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:44.078051 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.078552 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:44.233476 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.155s	user 0.128s	sys 0.021s 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":263,"lbm_read_time_us":10779,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32187,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:44.235136 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:44.288225 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.053s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22338,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.288764 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:44.300822 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.301332 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:44.466389 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.165s	user 0.123s	sys 0.031s 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":269,"lbm_read_time_us":10921,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34665,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.467049 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=14.095187
I20260812 06:17:44.521287 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.054s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19419,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.521844 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=2.188937
I20260812 06:17:44.533882 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102661,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.534657 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:44.566733 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushMRSOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":1442,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2205,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:44.567600 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): free 124710526 bytes of WAL
I20260812 06:17:44.567898 27209 log_reader.cc:385] T 5132d2ba7d7d4b1da610d4c72ebaa2d6: removed 12 log segments from log reader
I20260812 06:17:44.567975 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000028 (ops 136-140)
I20260812 06:17:44.568042 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000029 (ops 141-145)
I20260812 06:17:44.568100 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000030 (ops 146-150)
I20260812 06:17:44.568163 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000031 (ops 151-155)
I20260812 06:17:44.568207 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000032 (ops 156-160)
I20260812 06:17:44.568248 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000033 (ops 161-165)
I20260812 06:17:44.568289 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000034 (ops 166-170)
I20260812 06:17:44.568320 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000035 (ops 171-175)
I20260812 06:17:44.568360 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000036 (ops 176-180)
I20260812 06:17:44.568408 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000037 (ops 181-185)
I20260812 06:17:44.568452 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000038 (ops 186-190)
I20260812 06:17:44.568490 27209 log.cc:1079] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/5132d2ba7d7d4b1da610d4c72ebaa2d6/wal-000000039 (ops 191-195)
I20260812 06:17:44.596755 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: LogGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:44.597369 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=3.181125
I20260812 06:17:44.604328 27096 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.407s	user 2.032s	sys 0.139s
I20260812 06:17:44.609560 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":5169287,"delete_count":0,"lbm_write_time_us":5241,"lbm_writes_lt_1ms":129,"reinsert_count":0,"update_count":630}
I20260812 06:17:44.609967 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.196750
I20260812 06:17:44.617929 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: FlushDeltaMemStoresOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":2996,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:17:44.618366 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): 496 bytes on disk
I20260812 06:17:44.618822 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: UndoDeltaBlockGCOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.619421 27278 maintenance_manager.cc:419] P 978ef2c64c3a4c02822ed77dec02a07f: Scheduling MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6): perf score=1.000000
I20260812 06:17:44.684723 27096 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.002s	sys 0.000s
I20260812 06:17:44.685371 27096 tablet_server.cc:179] TabletServer@127.26.118.1:0 shutting down...
I20260812 06:17:44.779564 27209 maintenance_manager.cc:643] P 978ef2c64c3a4c02822ed77dec02a07f: MajorDeltaCompactionOp(5132d2ba7d7d4b1da610d4c72ebaa2d6) complete. Timing: real 0.160s	user 0.108s	sys 0.051s Metrics: {"cfile_cache_hit":227,"cfile_cache_hit_bytes":9234277,"cfile_cache_miss":507,"cfile_cache_miss_bytes":23745451,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":219,"lbm_read_time_us":9964,"lbm_reads_lt_1ms":543,"lbm_write_time_us":32661,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":112896,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:17:44.780827 27096 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:44.781844 27096 tablet_replica.cc:333] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f: stopping tablet replica
I20260812 06:17:44.782116 27096 raft_consensus.cc:2243] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:44.782356 27096 raft_consensus.cc:2272] T 5132d2ba7d7d4b1da610d4c72ebaa2d6 P 978ef2c64c3a4c02822ed77dec02a07f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:44.797827 27096 tablet_server.cc:196] TabletServer@127.26.118.1:0 shutdown complete.
I20260812 06:17:44.839504 27096 master.cc:562] Master@127.26.118.62:34369 shutting down...
I20260812 06:17:44.843488 27096 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:44.843704 27096 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:44.843803 27096 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9bfc8cfe91c24c53968cfbea314bdbb8: stopping tablet replica
I20260812 06:17:44.856523 27096 master.cc:584] Master@127.26.118.62:34369 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6047 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:44.946367 27096 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.118.62:42641
I20260812 06:17:44.946887 27096 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:44.949153 27313 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:17:44.949226 27314 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:17:44.949265 27316 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:17:44.949645 27096 server_base.cc:1061] running on GCE node
I20260812 06:17:44.949826 27096 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:44.949882 27096 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:17:44.949905 27096 hybrid_clock.cc:648] HybridClock initialized: now 1786515464949905 us; error 0 us; skew 500 ppm
I20260812 06:17:44.950935 27096 webserver.cc:533] Webserver started at http://127.26.118.62:45071/ using document root <none> and password file <none>
I20260812 06:17:44.951128 27096 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:44.951197 27096 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:44.951278 27096 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:44.951719 27096 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/master-0-root/instance:
uuid: "897f031633fa475580769e39d6035e91"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-pgkr"
I20260812 06:17:44.953363 27096 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:44.954396 27321 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:17:44.954716 27096 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:44.954811 27096 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/master-0-root
uuid: "897f031633fa475580769e39d6035e91"
format_stamp: "Formatted at 2026-08-12 06:17:44 on dist-test-slave-pgkr"
I20260812 06:17:44.954916 27096 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-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:17:44.987282 27096 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:44.987757 27096 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:44.992254 27096 rpc_server.cc:307] RPC server started. Bound to: 127.26.118.62:42641
I20260812 06:17:45.005786 27386 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:17:45.012782 27385 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.118.62:42641 every 8 connection(s)
I20260812 06:17:45.014302 27386 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91: Bootstrap starting.
I20260812 06:17:45.015296 27386 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.016484 27386 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91: No bootstrap required, opened a new log
I20260812 06:17:45.016919 27386 raft_consensus.cc:359] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "897f031633fa475580769e39d6035e91" member_type: VOTER }
I20260812 06:17:45.017035 27386 raft_consensus.cc:385] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.017091 27386 raft_consensus.cc:740] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 897f031633fa475580769e39d6035e91, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.017284 27386 consensus_queue.cc:260] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [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: "897f031633fa475580769e39d6035e91" member_type: VOTER }
I20260812 06:17:45.017412 27386 raft_consensus.cc:399] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.017462 27386 raft_consensus.cc:493] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.017521 27386 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.018287 27386 raft_consensus.cc:515] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "897f031633fa475580769e39d6035e91" member_type: VOTER }
I20260812 06:17:45.018474 27386 leader_election.cc:304] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [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: 897f031633fa475580769e39d6035e91; no voters: 
I20260812 06:17:45.018759 27386 leader_election.cc:290] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.018916 27389 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.019174 27389 raft_consensus.cc:697] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 1 LEADER]: Becoming Leader. State: Replica: 897f031633fa475580769e39d6035e91, State: Running, Role: LEADER
I20260812 06:17:45.019268 27386 sys_catalog.cc:565] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:45.019347 27389 consensus_queue.cc:237] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [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: "897f031633fa475580769e39d6035e91" member_type: VOTER }
I20260812 06:17:45.019822 27390 sys_catalog.cc:455] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "897f031633fa475580769e39d6035e91" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "897f031633fa475580769e39d6035e91" member_type: VOTER } }
I20260812 06:17:45.019951 27390 sys_catalog.cc:458] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.019829 27391 sys_catalog.cc:455] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 897f031633fa475580769e39d6035e91. Latest consensus state: current_term: 1 leader_uuid: "897f031633fa475580769e39d6035e91" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "897f031633fa475580769e39d6035e91" member_type: VOTER } }
I20260812 06:17:45.020124 27391 sys_catalog.cc:458] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.020573 27394 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:45.021257 27394 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:45.021502 27096 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:45.023250 27394 catalog_manager.cc:1383] Generated new cluster ID: d558ee188ecc4edc9f7356dd6ac753b1
I20260812 06:17:45.023316 27394 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:45.036818 27394 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:45.037496 27394 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:45.043171 27394 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91: Generated new TSK 0
I20260812 06:17:45.043375 27394 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:45.054448 27096 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.056668 27408 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:17:45.056775 27412 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:17:45.056835 27096 server_base.cc:1061] running on GCE node
W20260812 06:17:45.056679 27407 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:17:45.057077 27096 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.057197 27096 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:17:45.057273 27096 hybrid_clock.cc:648] HybridClock initialized: now 1786515465057273 us; error 0 us; skew 500 ppm
I20260812 06:17:45.058295 27096 webserver.cc:533] Webserver started at http://127.26.118.1:39305/ using document root <none> and password file <none>
I20260812 06:17:45.058482 27096 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.058565 27096 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.058701 27096 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.059114 27096 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/instance:
uuid: "bc7c18de05c14ca39ad74d7c0457e484"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-pgkr"
I20260812 06:17:45.060786 27096 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:45.061968 27417 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:17:45.062312 27096 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:45.062397 27096 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root
uuid: "bc7c18de05c14ca39ad74d7c0457e484"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-pgkr"
I20260812 06:17:45.062481 27096 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-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:17:45.088356 27096 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.088864 27096 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.089233 27096 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:45.089781 27096 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:45.089823 27096 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.089859 27096 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:45.089915 27096 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.094758 27096 rpc_server.cc:307] RPC server started. Bound to: 127.26.118.1:45109
I20260812 06:17:45.094789 27487 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.118.1:45109 every 8 connection(s)
I20260812 06:17:45.105134 27488 heartbeater.cc:344] Connected to a master server at 127.26.118.62:42641
I20260812 06:17:45.105275 27488 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:45.105551 27488 heartbeater.cc:507] Master 127.26.118.62:42641 requested a full tablet report, sending...
I20260812 06:17:45.106205 27341 ts_manager.cc:194] Registered new tserver with Master: bc7c18de05c14ca39ad74d7c0457e484 (127.26.118.1:45109)
I20260812 06:17:45.106436 27096 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011218992s
I20260812 06:17:45.107015 27341 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59082
I20260812 06:17:45.113965 27341 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59096:
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:17:45.123378 27449 tablet_service.cc:1511] Processing CreateTablet for tablet 78ee8f84c6a04d549dfb60f7f74c64f3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f9de470ef5564853b7f3af70eafa7283]), partition=
I20260812 06:17:45.123747 27449 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 78ee8f84c6a04d549dfb60f7f74c64f3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:45.126158 27502 tablet_bootstrap.cc:492] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Bootstrap starting.
I20260812 06:17:45.127110 27502 tablet_bootstrap.cc:654] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.128326 27502 tablet_bootstrap.cc:492] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: No bootstrap required, opened a new log
I20260812 06:17:45.128437 27502 ts_tablet_manager.cc:1403] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:45.128927 27502 raft_consensus.cc:359] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc7c18de05c14ca39ad74d7c0457e484" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 45109 } }
I20260812 06:17:45.129041 27502 raft_consensus.cc:385] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.129101 27502 raft_consensus.cc:740] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bc7c18de05c14ca39ad74d7c0457e484, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.129262 27502 consensus_queue.cc:260] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [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: "bc7c18de05c14ca39ad74d7c0457e484" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 45109 } }
I20260812 06:17:45.129370 27502 raft_consensus.cc:399] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.129419 27502 raft_consensus.cc:493] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.129473 27502 raft_consensus.cc:3060] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.130201 27502 raft_consensus.cc:515] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc7c18de05c14ca39ad74d7c0457e484" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 45109 } }
I20260812 06:17:45.130355 27502 leader_election.cc:304] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [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: bc7c18de05c14ca39ad74d7c0457e484; no voters: 
I20260812 06:17:45.130586 27502 leader_election.cc:290] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.130782 27504 raft_consensus.cc:2804] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.130968 27488 heartbeater.cc:499] Master 127.26.118.62:42641 was elected leader, sending a full tablet report...
I20260812 06:17:45.130985 27504 raft_consensus.cc:697] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 1 LEADER]: Becoming Leader. State: Replica: bc7c18de05c14ca39ad74d7c0457e484, State: Running, Role: LEADER
I20260812 06:17:45.130955 27502 ts_tablet_manager.cc:1434] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:45.131165 27504 consensus_queue.cc:237] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [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: "bc7c18de05c14ca39ad74d7c0457e484" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 45109 } }
I20260812 06:17:45.132524 27341 catalog_manager.cc:5719] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 reported cstate change: term changed from 0 to 1, leader changed from <none> to bc7c18de05c14ca39ad74d7c0457e484 (127.26.118.1). New cstate: current_term: 1 leader_uuid: "bc7c18de05c14ca39ad74d7c0457e484" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bc7c18de05c14ca39ad74d7c0457e484" member_type: VOTER last_known_addr { host: "127.26.118.1" port: 45109 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:45.192404 27096 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.004s
I20260812 06:17:45.345765 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=19.054940
I20260812 06:17:45.496206 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.150s	user 0.104s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1046,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38228,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:45.496958 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): free 20290830 bytes of WAL
I20260812 06:17:45.497246 27423 log_reader.cc:385] T 78ee8f84c6a04d549dfb60f7f74c64f3: removed 2 log segments from log reader
I20260812 06:17:45.497326 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000001 (ops 1-6)
I20260812 06:17:45.497381 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000002 (ops 7-10)
I20260812 06:17:45.501631 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:45.502135 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): 16411393 bytes on disk
I20260812 06:17:45.502676 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.503113 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:45.519773 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.520493 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:45.658248 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.138s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":64,"lbm_read_time_us":9824,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23817,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":245,"threads_started":5,"update_count":2000}
I20260812 06:17:45.658797 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:45.708051 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22318,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.708566 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:45.721343 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.722014 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:45.902777 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.180s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1229,"lbm_read_time_us":12471,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31230,"lbm_writes_lt_1ms":543,"mutex_wait_us":385,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":87168,"update_count":2500}
I20260812 06:17:45.903324 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:45.948361 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.948832 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:46.103880 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.155s	user 0.091s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":157,"lbm_read_time_us":10644,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25667,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.104688 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:46.161298 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.056s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26382,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.161783 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:46.173555 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.174015 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:46.363160 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.189s	user 0.110s	sys 0.070s 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":380,"lbm_read_time_us":13188,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29367,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:46.363735 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:46.417641 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.054s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24545,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.418232 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:46.436753 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.437667 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:46.611352 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.173s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":12215,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33815,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:46.611866 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:46.668790 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.057s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21864,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.669348 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:46.685508 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.686333 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:46.718918 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.032s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2000,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:46.719502 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): free 112239305 bytes of WAL
I20260812 06:17:46.719731 27423 log_reader.cc:385] T 78ee8f84c6a04d549dfb60f7f74c64f3: removed 11 log segments from log reader
I20260812 06:17:46.719774 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000003 (ops 11-15)
I20260812 06:17:46.719802 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000004 (ops 16-20)
I20260812 06:17:46.719861 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000005 (ops 21-25)
I20260812 06:17:46.719909 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000006 (ops 26-30)
I20260812 06:17:46.719952 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000007 (ops 31-35)
I20260812 06:17:46.720012 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000008 (ops 36-40)
I20260812 06:17:46.720062 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000009 (ops 41-45)
I20260812 06:17:46.720099 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000010 (ops 46-50)
I20260812 06:17:46.720136 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000011 (ops 51-55)
I20260812 06:17:46.720175 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000012 (ops 56-60)
I20260812 06:17:46.720213 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000013 (ops 61-64)
I20260812 06:17:46.744728 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:46.745101 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): 447 bytes on disk
I20260812 06:17:46.745505 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.746061 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=3.181125
I20260812 06:17:46.770455 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.024s	user 0.007s	sys 0.013s Metrics: {"bytes_written":4718029,"delete_count":0,"lbm_write_time_us":5351,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:17:46.770985 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:46.782263 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.007s	sys 0.002s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:17:46.782753 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:47.042923 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.260s	user 0.162s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":938,"lbm_read_time_us":16006,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40411,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:17:47.043723 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=18.063937
I20260812 06:17:47.119290 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.075s	user 0.035s	sys 0.028s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":28669,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:47.119843 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:47.130921 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.131464 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:47.339900 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.208s	user 0.148s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1152,"lbm_read_time_us":13367,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33958,"lbm_writes_lt_1ms":643,"mutex_wait_us":319,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:17:47.341537 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=16.079562
I20260812 06:17:47.402016 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.060s	user 0.025s	sys 0.028s Metrics: {"bytes_written":17640640,"delete_count":0,"lbm_write_time_us":25656,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:17:47.402562 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:47.420652 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.018s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":5859,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:17:47.421159 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:47.431870 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.432408 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:47.655429 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.223s	user 0.152s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":769,"lbm_read_time_us":16780,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36457,"lbm_writes_lt_1ms":643,"mutex_wait_us":333,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":47360,"update_count":3000}
I20260812 06:17:47.656397 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:47.716717 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.060s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26236,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.717235 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:47.737592 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.020s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4550,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.738019 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:47.749385 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.749935 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:47.967666 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.217s	user 0.170s	sys 0.047s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":321,"lbm_read_time_us":14383,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36490,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:17:47.968466 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:48.019088 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.048s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":21115,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:48.019611 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:48.036098 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.036576 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:48.046890 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.047366 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:48.239568 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.192s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":602,"lbm_read_time_us":14228,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31902,"lbm_writes_lt_1ms":643,"mutex_wait_us":275,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:17:48.240156 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=16.079562
I20260812 06:17:48.308817 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.068s	user 0.018s	sys 0.036s Metrics: {"bytes_written":17845751,"delete_count":0,"lbm_write_time_us":26784,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2175}
I20260812 06:17:48.309290 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=5.165500
I20260812 06:17:48.327255 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":6769241,"delete_count":0,"lbm_write_time_us":7496,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:17:48.327744 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:48.360021 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1499,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1558,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:48.360738 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): free 133024382 bytes of WAL
I20260812 06:17:48.361064 27423 log_reader.cc:385] T 78ee8f84c6a04d549dfb60f7f74c64f3: removed 13 log segments from log reader
I20260812 06:17:48.361145 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000014 (ops 65-69)
I20260812 06:17:48.361241 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000015 (ops 70-74)
I20260812 06:17:48.361317 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000016 (ops 75-79)
I20260812 06:17:48.361388 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000017 (ops 80-84)
I20260812 06:17:48.361455 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000018 (ops 85-89)
I20260812 06:17:48.361527 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000019 (ops 90-94)
I20260812 06:17:48.361595 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000020 (ops 95-99)
I20260812 06:17:48.361698 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000021 (ops 100-104)
I20260812 06:17:48.361773 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000022 (ops 105-109)
I20260812 06:17:48.361845 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000023 (ops 110-114)
I20260812 06:17:48.361922 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000024 (ops 115-119)
I20260812 06:17:48.361987 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000025 (ops 120-124)
I20260812 06:17:48.362069 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000026 (ops 125-128)
I20260812 06:17:48.396104 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:48.396703 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): 491 bytes on disk
I20260812 06:17:48.397445 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.398017 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=6.157687
I20260812 06:17:48.419607 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":7999957,"delete_count":0,"lbm_write_time_us":9134,"lbm_writes_lt_1ms":198,"reinsert_count":0,"update_count":975}
I20260812 06:17:48.420064 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:48.663165 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.243s	user 0.167s	sys 0.076s Metrics: {"cfile_cache_miss":828,"cfile_cache_miss_bytes":36876937,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":820,"lbm_read_time_us":17561,"lbm_reads_lt_1ms":864,"lbm_write_time_us":44788,"lbm_writes_lt_1ms":838,"mutex_wait_us":81,"peak_mem_usage":99150057,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":80,"threads_started":1,"update_count":3975}
I20260812 06:17:48.663992 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=19.056125
I20260812 06:17:48.730134 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.066s	user 0.018s	sys 0.044s Metrics: {"bytes_written":20717441,"delete_count":0,"lbm_write_time_us":30188,"lbm_writes_lt_1ms":508,"reinsert_count":0,"update_count":2525}
I20260812 06:17:48.731194 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:48.749224 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.749738 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:48.910691 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.161s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":637,"cfile_cache_miss_bytes":29082227,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":709,"lbm_read_time_us":11869,"lbm_reads_lt_1ms":669,"lbm_write_time_us":33664,"lbm_writes_lt_1ms":648,"peak_mem_usage":75747647,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3025}
I20260812 06:17:48.911479 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:48.960525 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.049s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20112,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.961050 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:48.985817 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.025s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.986285 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:48.996692 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.997128 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:49.168985 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.172s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1248,"lbm_read_time_us":11678,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37269,"lbm_writes_lt_1ms":643,"mutex_wait_us":302,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:49.169530 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:49.221055 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.051s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19956,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.221637 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:49.235405 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.235888 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:49.393332 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.157s	user 0.105s	sys 0.047s 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":1336,"lbm_read_time_us":12144,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27714,"lbm_writes_lt_1ms":543,"mutex_wait_us":609,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:49.394110 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:49.458101 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.064s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23929,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.458730 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:49.470191 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.470849 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:49.652164 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.181s	user 0.112s	sys 0.065s 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":1458,"lbm_read_time_us":13194,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30049,"lbm_writes_lt_1ms":543,"mutex_wait_us":193,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:17:49.652835 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=14.095187
I20260812 06:17:49.708498 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.055s	user 0.029s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.709060 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:49.721850 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.722579 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:49.755442 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushMRSOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":157,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1685,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:49.756359 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): free 120553651 bytes of WAL
I20260812 06:17:49.756618 27423 log_reader.cc:385] T 78ee8f84c6a04d549dfb60f7f74c64f3: removed 12 log segments from log reader
I20260812 06:17:49.756668 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000027 (ops 129-133)
I20260812 06:17:49.756701 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000028 (ops 134-138)
I20260812 06:17:49.756770 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000029 (ops 139-142)
I20260812 06:17:49.756817 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000030 (ops 143-147)
I20260812 06:17:49.756860 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000031 (ops 148-152)
I20260812 06:17:49.756912 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000032 (ops 153-157)
I20260812 06:17:49.756953 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000033 (ops 158-162)
I20260812 06:17:49.756991 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000034 (ops 163-167)
I20260812 06:17:49.757035 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000035 (ops 168-172)
I20260812 06:17:49.757073 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000036 (ops 173-176)
I20260812 06:17:49.757122 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000037 (ops 177-181)
I20260812 06:17:49.757162 27423 log.cc:1079] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: Deleting log segment in path: /tmp/dist-test-taskdsUD6t/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515458888346-27096-0/minicluster-data/ts-0-root/wals/78ee8f84c6a04d549dfb60f7f74c64f3/wal-000000038 (ops 182-186)
I20260812 06:17:49.784834 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: LogGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:49.785347 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=3.181125
I20260812 06:17:49.801914 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:49.802387 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3): 462 bytes on disk
I20260812 06:17:49.802872 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: UndoDeltaBlockGCOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.803385 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:49.814217 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.814754 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:50.041225 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.226s	user 0.141s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":262,"lbm_read_time_us":17612,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39181,"lbm_writes_lt_1ms":743,"mutex_wait_us":34,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:17:50.042554 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=15.087375
I20260812 06:17:50.073411 27096 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.881s	user 1.840s	sys 0.140s
I20260812 06:17:50.104262 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.061s	user 0.026s	sys 0.033s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":26288,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:50.104941 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=2.188937
I20260812 06:17:50.114179 27096 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.001s	sys 0.000s
I20260812 06:17:50.114717 27096 tablet_server.cc:179] TabletServer@127.26.118.1:0 shutting down...
I20260812 06:17:50.117393 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: FlushDeltaMemStoresOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.118003 27489 maintenance_manager.cc:419] P bc7c18de05c14ca39ad74d7c0457e484: Scheduling MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3): perf score=1.000000
I20260812 06:17:50.235699 27423 maintenance_manager.cc:643] P bc7c18de05c14ca39ad74d7c0457e484: MajorDeltaCompactionOp(78ee8f84c6a04d549dfb60f7f74c64f3) complete. Timing: real 0.117s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512285,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":461,"lbm_read_time_us":7728,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23684,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:50.236588 27096 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:50.236848 27096 tablet_replica.cc:333] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484: stopping tablet replica
I20260812 06:17:50.237008 27096 raft_consensus.cc:2243] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.237191 27096 raft_consensus.cc:2272] T 78ee8f84c6a04d549dfb60f7f74c64f3 P bc7c18de05c14ca39ad74d7c0457e484 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.241959 27096 tablet_server.cc:196] TabletServer@127.26.118.1:0 shutdown complete.
I20260812 06:17:50.282285 27096 master.cc:562] Master@127.26.118.62:42641 shutting down...
I20260812 06:17:50.286238 27096 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.286603 27096 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.286749 27096 tablet_replica.cc:333] T 00000000000000000000000000000000 P 897f031633fa475580769e39d6035e91: stopping tablet replica
I20260812 06:17:50.299644 27096 master.cc:584] Master@127.26.118.62:42641 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5447 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11495 ms total)

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