[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:42.418033 18161 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.188.126:34999
I20260812 06:16:42.420609 18161 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:42.421185 18161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.427294 18171 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:42.427390 18161 server_base.cc:1061] running on GCE node
W20260812 06:16:42.427534 18170 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:42.427583 18174 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:42.428040 18161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.428138 18161 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:42.428180 18161 hybrid_clock.cc:648] HybridClock initialized: now 1786515402428178 us; error 0 us; skew 500 ppm
I20260812 06:16:42.429800 18161 webserver.cc:533] Webserver started at http://127.17.188.126:38115/ using document root <none> and password file <none>
I20260812 06:16:42.430284 18161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.430341 18161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.430557 18161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.432128 18161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/master-0-root/instance:
uuid: "af3f8fb93a244d1d8dc0feea3db65acf"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-1vmg"
I20260812 06:16:42.435310 18161 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:42.437095 18183 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.437978 18161 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:42.438077 18161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/master-0-root
uuid: "af3f8fb93a244d1d8dc0feea3db65acf"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-1vmg"
I20260812 06:16:42.438160 18161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:42.472600 18161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.473243 18161 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:42.473402 18161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.480557 18280 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.188.126:34999 every 8 connection(s)
I20260812 06:16:42.480561 18161 rpc_server.cc:307] RPC server started. Bound to: 127.17.188.126:34999
I20260812 06:16:42.482752 18282 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.487995 18282 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: Bootstrap starting.
I20260812 06:16:42.490257 18282 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.491137 18282 log.cc:826] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:42.492692 18282 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: No bootstrap required, opened a new log
I20260812 06:16:42.495383 18282 raft_consensus.cc:359] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER }
I20260812 06:16:42.495537 18282 raft_consensus.cc:385] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.495592 18282 raft_consensus.cc:740] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af3f8fb93a244d1d8dc0feea3db65acf, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.496088 18282 consensus_queue.cc:260] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [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: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER }
I20260812 06:16:42.496217 18282 raft_consensus.cc:399] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.496263 18282 raft_consensus.cc:493] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.496345 18282 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.497032 18282 raft_consensus.cc:515] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER }
I20260812 06:16:42.497402 18282 leader_election.cc:304] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [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: af3f8fb93a244d1d8dc0feea3db65acf; no voters: 
I20260812 06:16:42.497659 18282 leader_election.cc:290] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.497771 18290 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.497984 18290 raft_consensus.cc:697] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 1 LEADER]: Becoming Leader. State: Replica: af3f8fb93a244d1d8dc0feea3db65acf, State: Running, Role: LEADER
I20260812 06:16:42.498370 18290 consensus_queue.cc:237] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [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: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER }
I20260812 06:16:42.498581 18282 sys_catalog.cc:565] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:42.500202 18292 sys_catalog.cc:455] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [sys.catalog]: SysCatalogTable state changed. Reason: New leader af3f8fb93a244d1d8dc0feea3db65acf. Latest consensus state: current_term: 1 leader_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER } }
I20260812 06:16:42.500245 18291 sys_catalog.cc:455] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af3f8fb93a244d1d8dc0feea3db65acf" member_type: VOTER } }
I20260812 06:16:42.500329 18292 sys_catalog.cc:458] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.500334 18291 sys_catalog.cc:458] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.500667 18314 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:42.500836 18161 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:42.502836 18314 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:42.507064 18314 catalog_manager.cc:1383] Generated new cluster ID: dc64add0e9e848e2a8c92aef412fdb35
I20260812 06:16:42.507128 18314 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:42.521221 18314 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:42.522047 18314 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:42.532308 18314 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: Generated new TSK 0
I20260812 06:16:42.532938 18314 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:42.565606 18161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:42.568693 18161 server_base.cc:1061] running on GCE node
W20260812 06:16:42.568626 18329 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:42.568745 18336 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:42.568625 18332 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:42.569087 18161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.569144 18161 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:42.569164 18161 hybrid_clock.cc:648] HybridClock initialized: now 1786515402569164 us; error 0 us; skew 500 ppm
I20260812 06:16:42.570024 18161 webserver.cc:533] Webserver started at http://127.17.188.65:37611/ using document root <none> and password file <none>
I20260812 06:16:42.570194 18161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.570248 18161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.570327 18161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.570683 18161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/instance:
uuid: "a4b72483e5d24e8aac39860e5d3ca6cd"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-1vmg"
I20260812 06:16:42.572151 18161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:42.573041 18347 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.573256 18161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.573325 18161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root
uuid: "a4b72483e5d24e8aac39860e5d3ca6cd"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-1vmg"
I20260812 06:16:42.573391 18161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:42.595994 18161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.596402 18161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.596853 18161 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:42.597672 18161 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:42.597723 18161 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.597769 18161 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:42.597800 18161 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.603896 18161 rpc_server.cc:307] RPC server started. Bound to: 127.17.188.65:45597
I20260812 06:16:42.603935 18453 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.188.65:45597 every 8 connection(s)
I20260812 06:16:42.613283 18454 heartbeater.cc:344] Connected to a master server at 127.17.188.126:34999
I20260812 06:16:42.613521 18454 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:42.613978 18454 heartbeater.cc:507] Master 127.17.188.126:34999 requested a full tablet report, sending...
I20260812 06:16:42.615490 18205 ts_manager.cc:194] Registered new tserver with Master: a4b72483e5d24e8aac39860e5d3ca6cd (127.17.188.65:45597)
I20260812 06:16:42.615609 18161 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011159405s
I20260812 06:16:42.616983 18205 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39292
I20260812 06:16:42.625214 18205 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39296:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:42.639917 18393 tablet_service.cc:1511] Processing CreateTablet for tablet e0eaf4fd2da84eefad0e00639cf4caff (DEFAULT_TABLE table=heavy-update-compaction-test [id=a331cb20378b466d915dc7adcdbecb77]), partition=
I20260812 06:16:42.640367 18393 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e0eaf4fd2da84eefad0e00639cf4caff. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.642557 18475 tablet_bootstrap.cc:492] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Bootstrap starting.
I20260812 06:16:42.644085 18475 tablet_bootstrap.cc:654] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.645274 18475 tablet_bootstrap.cc:492] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: No bootstrap required, opened a new log
I20260812 06:16:42.645376 18475 ts_tablet_manager.cc:1403] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:42.645799 18475 raft_consensus.cc:359] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b72483e5d24e8aac39860e5d3ca6cd" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 45597 } }
I20260812 06:16:42.645905 18475 raft_consensus.cc:385] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.645939 18475 raft_consensus.cc:740] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4b72483e5d24e8aac39860e5d3ca6cd, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.646056 18475 consensus_queue.cc:260] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [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: "a4b72483e5d24e8aac39860e5d3ca6cd" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 45597 } }
I20260812 06:16:42.646129 18475 raft_consensus.cc:399] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.646168 18475 raft_consensus.cc:493] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.646210 18475 raft_consensus.cc:3060] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.647042 18475 raft_consensus.cc:515] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b72483e5d24e8aac39860e5d3ca6cd" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 45597 } }
I20260812 06:16:42.647178 18475 leader_election.cc:304] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [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: a4b72483e5d24e8aac39860e5d3ca6cd; no voters: 
I20260812 06:16:42.647352 18475 leader_election.cc:290] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.647487 18484 raft_consensus.cc:2804] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.647670 18475 ts_tablet_manager.cc:1434] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:42.647743 18484 raft_consensus.cc:697] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 1 LEADER]: Becoming Leader. State: Replica: a4b72483e5d24e8aac39860e5d3ca6cd, State: Running, Role: LEADER
I20260812 06:16:42.647893 18454 heartbeater.cc:499] Master 127.17.188.126:34999 was elected leader, sending a full tablet report...
I20260812 06:16:42.647931 18484 consensus_queue.cc:237] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [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: "a4b72483e5d24e8aac39860e5d3ca6cd" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 45597 } }
I20260812 06:16:42.650424 18205 catalog_manager.cc:5719] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd reported cstate change: term changed from 0 to 1, leader changed from <none> to a4b72483e5d24e8aac39860e5d3ca6cd (127.17.188.65). New cstate: current_term: 1 leader_uuid: "a4b72483e5d24e8aac39860e5d3ca6cd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4b72483e5d24e8aac39860e5d3ca6cd" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 45597 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.707779 18161 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.023s	sys 0.000s
I20260812 06:16:42.854969 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=19.054940
I20260812 06:16:43.042171 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.187s	user 0.137s	sys 0.040s Metrics: {"bytes_written":16450925,"cfile_init":1,"compiler_manager_pool.queue_time_us":175,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":861,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48049,"lbm_writes_lt_1ms":858,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":355200,"thread_start_us":103,"threads_started":1,"update_count":2005}
I20260812 06:16:43.043258 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff): 16411396 bytes on disk
I20260812 06:16:43.043859 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff) 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:16:43.044268 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=3.181125
I20260812 06:16:43.058560 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":5005194,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:16:43.059048 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff): free 20743880 bytes of WAL
I20260812 06:16:43.059388 18355 log_reader.cc:385] T e0eaf4fd2da84eefad0e00639cf4caff: removed 2 log segments from log reader
I20260812 06:16:43.059506 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000001 (ops 1-6)
I20260812 06:16:43.059608 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000002 (ops 7-11)
I20260812 06:16:43.064337 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:43.064633 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.196750
I20260812 06:16:43.074993 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:43.075349 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:43.249384 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.174s	user 0.117s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877199,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":463,"lbm_read_time_us":12310,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31395,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":282,"threads_started":5,"update_count":3000}
I20260812 06:16:43.249852 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:43.297780 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.048s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17316,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.298252 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:43.309906 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.310335 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:43.457315 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.147s	user 0.106s	sys 0.040s 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":1143,"lbm_read_time_us":10106,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24172,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:43.458282 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:43.495745 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.496228 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:43.506269 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.506755 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:43.631986 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.125s	user 0.081s	sys 0.041s 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":156,"lbm_read_time_us":9525,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23671,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.632469 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:43.676512 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.044s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16311,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.676970 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:43.686645 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.687172 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:43.803364 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.116s	user 0.093s	sys 0.022s 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":810,"lbm_read_time_us":7979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22304,"lbm_writes_lt_1ms":443,"mutex_wait_us":17,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:16:43.803797 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:43.835867 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.032s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.836289 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:43.845911 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.846264 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:43.962118 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.116s	user 0.108s	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":683,"lbm_read_time_us":7518,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23684,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:43.962580 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:44.010356 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.048s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17308,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.010815 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:44.020406 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.020782 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:44.160517 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.140s	user 0.099s	sys 0.040s 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":143,"lbm_read_time_us":10748,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22984,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:16:44.163002 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:44.200136 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.037s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16016,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.200670 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:44.218405 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.218904 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:44.249364 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1839,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:44.250203 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff): free 124710311 bytes of WAL
I20260812 06:16:44.250412 18355 log_reader.cc:385] T e0eaf4fd2da84eefad0e00639cf4caff: removed 12 log segments from log reader
I20260812 06:16:44.250463 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000003 (ops 12-16)
I20260812 06:16:44.250505 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000004 (ops 17-21)
I20260812 06:16:44.250545 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000005 (ops 22-26)
I20260812 06:16:44.250583 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000006 (ops 27-31)
I20260812 06:16:44.250617 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000007 (ops 32-36)
I20260812 06:16:44.250650 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000008 (ops 37-41)
I20260812 06:16:44.250681 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000009 (ops 42-46)
I20260812 06:16:44.250707 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000010 (ops 47-51)
I20260812 06:16:44.250751 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000011 (ops 52-56)
I20260812 06:16:44.250789 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000012 (ops 57-61)
I20260812 06:16:44.250818 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000013 (ops 62-66)
I20260812 06:16:44.250846 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000014 (ops 67-71)
I20260812 06:16:44.273618 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:16:44.273942 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff): 482 bytes on disk
I20260812 06:16:44.274336 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff) 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:16:44.274791 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=6.157687
I20260812 06:16:44.298887 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.024s	user 0.010s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8430,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.299381 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:44.481287 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.182s	user 0.121s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1965,"lbm_read_time_us":12710,"lbm_reads_lt_1ms":665,"lbm_write_time_us":31612,"lbm_writes_lt_1ms":643,"mutex_wait_us":964,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:16:44.482090 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=14.095187
I20260812 06:16:44.530185 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.048s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.530721 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:44.540545 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.540969 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:44.721933 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.181s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":569,"lbm_read_time_us":12396,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29484,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":59904,"update_count":2500}
I20260812 06:16:44.722354 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=14.095187
I20260812 06:16:44.763733 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.041s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17943,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.764307 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:44.775712 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.776098 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:44.940966 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.165s	user 0.116s	sys 0.043s 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":140,"lbm_read_time_us":9620,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28238,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.941417 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=14.095187
I20260812 06:16:44.991540 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.050s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20097,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.991973 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:45.003086 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.003473 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:45.159377 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.156s	user 0.101s	sys 0.052s 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":524,"lbm_read_time_us":10792,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29289,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.160013 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:45.204777 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.045s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19186,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.205375 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:45.219477 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.219974 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:45.351797 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.132s	user 0.104s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":70,"lbm_read_time_us":7886,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28036,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:45.354795 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=11.118625
I20260812 06:16:45.396791 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.041s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15910,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:45.397310 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:45.410859 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4976,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.411384 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:45.531406 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.119s	user 0.079s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":8282,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23503,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.531895 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:45.581018 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.049s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13813,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.581557 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:45.596459 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.596900 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:45.625602 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1228,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1224,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:45.626263 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:45.763559 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.137s	user 0.082s	sys 0.047s 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":187,"lbm_read_time_us":8119,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20476,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.764124 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff): free 112692371 bytes of WAL
I20260812 06:16:45.764328 18355 log_reader.cc:385] T e0eaf4fd2da84eefad0e00639cf4caff: removed 11 log segments from log reader
I20260812 06:16:45.764369 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000015 (ops 72-76)
I20260812 06:16:45.764407 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000016 (ops 77-81)
I20260812 06:16:45.764442 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000017 (ops 82-86)
I20260812 06:16:45.764506 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000018 (ops 87-91)
I20260812 06:16:45.764551 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000019 (ops 92-96)
I20260812 06:16:45.764602 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000020 (ops 97-101)
I20260812 06:16:45.764637 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000021 (ops 102-106)
I20260812 06:16:45.764694 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000022 (ops 107-111)
I20260812 06:16:45.764729 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000023 (ops 112-116)
I20260812 06:16:45.764788 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000024 (ops 117-121)
I20260812 06:16:45.764823 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000025 (ops 122-126)
I20260812 06:16:45.788699 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:45.789131 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff): 448 bytes on disk
I20260812 06:16:45.789711 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.790241 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=15.087375
I20260812 06:16:45.848585 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.058s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21451,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:16:45.849047 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=6.157687
I20260812 06:16:45.875727 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.027s	user 0.020s	sys 0.000s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8452,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:45.876372 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.048038 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.171s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":674,"lbm_read_time_us":12485,"lbm_reads_lt_1ms":664,"lbm_write_time_us":31663,"lbm_writes_lt_1ms":643,"mutex_wait_us":351,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:46.048642 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=14.095187
I20260812 06:16:46.104074 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.055s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.104568 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:46.114456 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.114938 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.273607 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.158s	user 0.109s	sys 0.045s 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":232,"lbm_read_time_us":11769,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25794,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:16:46.274212 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=11.118625
I20260812 06:16:46.309602 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.035s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14900,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.310245 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:46.327544 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5308,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.328131 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.455657 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.127s	user 0.065s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":8613,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23670,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.456328 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:46.490219 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.034s	user 0.027s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12900,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.490759 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:46.501493 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.011s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.502027 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.620671 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.118s	user 0.086s	sys 0.032s 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":147,"lbm_read_time_us":7300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24218,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:16:46.621191 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:46.663375 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.042s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15427,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.663825 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:46.673202 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3594,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.673727 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.779562 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.106s	user 0.094s	sys 0.012s 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":7586,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20307,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:16:46.780124 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:46.826427 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.046s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14715,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.826930 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:46.836427 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.836822 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:46.970590 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.134s	user 0.101s	sys 0.032s 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":714,"lbm_read_time_us":9935,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22648,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.971122 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=10.126437
I20260812 06:16:47.009472 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.038s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13839,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.009925 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=2.188937
I20260812 06:16:47.019662 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.020141 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:47.048624 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushMRSOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.028s	user 0.020s	sys 0.006s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":157,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1537,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:47.049347 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff): free 132118521 bytes of WAL
I20260812 06:16:47.049577 18355 log_reader.cc:385] T e0eaf4fd2da84eefad0e00639cf4caff: removed 13 log segments from log reader
I20260812 06:16:47.049639 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000026 (ops 127-131)
I20260812 06:16:47.049682 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000027 (ops 132-136)
I20260812 06:16:47.049713 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000028 (ops 137-141)
I20260812 06:16:47.049744 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000029 (ops 142-146)
I20260812 06:16:47.049778 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000030 (ops 147-150)
I20260812 06:16:47.049808 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000031 (ops 151-155)
I20260812 06:16:47.049836 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000032 (ops 156-160)
I20260812 06:16:47.049865 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000033 (ops 161-165)
I20260812 06:16:47.049896 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000034 (ops 166-170)
I20260812 06:16:47.049927 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000035 (ops 171-174)
I20260812 06:16:47.049957 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000036 (ops 175-179)
I20260812 06:16:47.049984 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000037 (ops 180-184)
I20260812 06:16:47.050011 18355 log.cc:1079] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/e0eaf4fd2da84eefad0e00639cf4caff/wal-000000038 (ops 185-188)
I20260812 06:16:47.077922 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: LogGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:47.078290 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff): 482 bytes on disk
I20260812 06:16:47.078699 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: UndoDeltaBlockGCOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.079253 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=3.181125
I20260812 06:16:47.101866 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.022s	user 0.016s	sys 0.004s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":5625,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:16:47.102298 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.196750
I20260812 06:16:47.109697 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":2728,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:16:47.110025 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=1.000000
I20260812 06:16:47.303238 18161 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.595s	user 1.660s	sys 0.156s
I20260812 06:16:47.306540 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: MajorDeltaCompactionOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.196s	user 0.121s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1485,"lbm_read_time_us":12993,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31756,"lbm_writes_lt_1ms":643,"mutex_wait_us":776,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:16:47.307156 18456 maintenance_manager.cc:419] P a4b72483e5d24e8aac39860e5d3ca6cd: Scheduling FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff): perf score=14.095187
I20260812 06:16:47.334493 18161 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.003s	sys 0.000s
I20260812 06:16:47.335723 18161 tablet_server.cc:179] TabletServer@127.17.188.65:0 shutting down...
I20260812 06:16:47.353175 18355 maintenance_manager.cc:643] P a4b72483e5d24e8aac39860e5d3ca6cd: FlushDeltaMemStoresOp(e0eaf4fd2da84eefad0e00639cf4caff) complete. Timing: real 0.046s	user 0.043s	sys 0.001s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.353811 18161 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.354241 18161 tablet_replica.cc:333] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd: stopping tablet replica
I20260812 06:16:47.354455 18161 raft_consensus.cc:2243] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.363925 18161 raft_consensus.cc:2272] T e0eaf4fd2da84eefad0e00639cf4caff P a4b72483e5d24e8aac39860e5d3ca6cd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.378362 18161 tablet_server.cc:196] TabletServer@127.17.188.65:0 shutdown complete.
I20260812 06:16:47.382970 18161 master.cc:562] Master@127.17.188.126:34999 shutting down...
I20260812 06:16:47.386623 18161 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.386782 18161 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.386865 18161 tablet_replica.cc:333] T 00000000000000000000000000000000 P af3f8fb93a244d1d8dc0feea3db65acf: stopping tablet replica
I20260812 06:16:47.398826 18161 master.cc:584] Master@127.17.188.126:34999 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5200 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:47.617748 18161 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.188.126:45663
I20260812 06:16:47.618145 18161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:47.620049 18511 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:47.620150 18516 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:47.620059 18509 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:47.620160 18161 server_base.cc:1061] running on GCE node
I20260812 06:16:47.620422 18161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.620461 18161 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:47.620481 18161 hybrid_clock.cc:648] HybridClock initialized: now 1786515407620481 us; error 0 us; skew 500 ppm
I20260812 06:16:47.621269 18161 webserver.cc:533] Webserver started at http://127.17.188.126:40763/ using document root <none> and password file <none>
I20260812 06:16:47.621423 18161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.621469 18161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.621544 18161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.621905 18161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/master-0-root/instance:
uuid: "b0667c5149b2409fadf41ba8f31d39d9"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-1vmg"
I20260812 06:16:47.623381 18161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:47.624204 18523 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.624408 18161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:47.624477 18161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/master-0-root
uuid: "b0667c5149b2409fadf41ba8f31d39d9"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-1vmg"
I20260812 06:16:47.624542 18161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:47.631829 18161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.632110 18161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.635725 18161 rpc_server.cc:307] RPC server started. Bound to: 127.17.188.126:45663
I20260812 06:16:47.640798 18604 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.188.126:45663 every 8 connection(s)
I20260812 06:16:47.641244 18605 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:47.642866 18605 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9: Bootstrap starting.
I20260812 06:16:47.643606 18605 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.644495 18605 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9: No bootstrap required, opened a new log
I20260812 06:16:47.644874 18605 raft_consensus.cc:359] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER }
I20260812 06:16:47.644954 18605 raft_consensus.cc:385] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.644984 18605 raft_consensus.cc:740] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b0667c5149b2409fadf41ba8f31d39d9, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.645121 18605 consensus_queue.cc:260] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [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: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER }
I20260812 06:16:47.645196 18605 raft_consensus.cc:399] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.645236 18605 raft_consensus.cc:493] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.645285 18605 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.645908 18605 raft_consensus.cc:515] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER }
I20260812 06:16:47.646032 18605 leader_election.cc:304] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [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: b0667c5149b2409fadf41ba8f31d39d9; no voters: 
I20260812 06:16:47.646193 18605 leader_election.cc:290] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.646281 18610 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.646484 18610 raft_consensus.cc:697] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 1 LEADER]: Becoming Leader. State: Replica: b0667c5149b2409fadf41ba8f31d39d9, State: Running, Role: LEADER
I20260812 06:16:47.646577 18605 sys_catalog.cc:565] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:47.646620 18610 consensus_queue.cc:237] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [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: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER }
I20260812 06:16:47.647042 18611 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b0667c5149b2409fadf41ba8f31d39d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER } }
I20260812 06:16:47.647073 18613 sys_catalog.cc:455] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b0667c5149b2409fadf41ba8f31d39d9. Latest consensus state: current_term: 1 leader_uuid: "b0667c5149b2409fadf41ba8f31d39d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0667c5149b2409fadf41ba8f31d39d9" member_type: VOTER } }
I20260812 06:16:47.647228 18613 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.647436 18611 sys_catalog.cc:458] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.647665 18623 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:47.648538 18623 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:47.648727 18161 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:47.650197 18623 catalog_manager.cc:1383] Generated new cluster ID: d4774d2064bc4d2b807c4de5dfd6be56
I20260812 06:16:47.650249 18623 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:47.660969 18623 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:47.661453 18623 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:47.669683 18623 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9: Generated new TSK 0
I20260812 06:16:47.669844 18623 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:47.680727 18161 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:47.682482 18638 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:47.682525 18161 server_base.cc:1061] running on GCE node
W20260812 06:16:47.682541 18639 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:47.682467 18647 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:47.682798 18161 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.682842 18161 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:47.682862 18161 hybrid_clock.cc:648] HybridClock initialized: now 1786515407682862 us; error 0 us; skew 500 ppm
I20260812 06:16:47.683621 18161 webserver.cc:533] Webserver started at http://127.17.188.65:37769/ using document root <none> and password file <none>
I20260812 06:16:47.683764 18161 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.683815 18161 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.683887 18161 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.684223 18161 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/instance:
uuid: "523e41dea09849019d2868cfffb0091e"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-1vmg"
I20260812 06:16:47.685554 18161 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:47.686363 18655 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.686578 18161 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:47.686643 18161 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root
uuid: "523e41dea09849019d2868cfffb0091e"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-1vmg"
I20260812 06:16:47.686707 18161 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:47.713869 18161 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.714205 18161 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.714468 18161 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:47.714875 18161 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:47.714941 18161 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.714995 18161 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:47.715026 18161 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.718850 18161 rpc_server.cc:307] RPC server started. Bound to: 127.17.188.65:32985
I20260812 06:16:47.719084 18781 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.188.65:32985 every 8 connection(s)
I20260812 06:16:47.726948 18782 heartbeater.cc:344] Connected to a master server at 127.17.188.126:45663
I20260812 06:16:47.727048 18782 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:47.727238 18782 heartbeater.cc:507] Master 127.17.188.126:45663 requested a full tablet report, sending...
I20260812 06:16:47.727809 18549 ts_manager.cc:194] Registered new tserver with Master: 523e41dea09849019d2868cfffb0091e (127.17.188.65:32985)
I20260812 06:16:47.728040 18161 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008720092s
I20260812 06:16:47.728492 18549 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33024
I20260812 06:16:47.734125 18549 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33032:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:47.741700 18705 tablet_service.cc:1511] Processing CreateTablet for tablet ea6d87a4a08247a08ee713ff1beb7905 (DEFAULT_TABLE table=heavy-update-compaction-test [id=05e933adb0d8427fa2ae10d6a4827112]), partition=
I20260812 06:16:47.741926 18705 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ea6d87a4a08247a08ee713ff1beb7905. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:47.743674 18799 tablet_bootstrap.cc:492] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Bootstrap starting.
I20260812 06:16:47.744594 18799 tablet_bootstrap.cc:654] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.745524 18799 tablet_bootstrap.cc:492] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: No bootstrap required, opened a new log
I20260812 06:16:47.745604 18799 ts_tablet_manager.cc:1403] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:47.745975 18799 raft_consensus.cc:359] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "523e41dea09849019d2868cfffb0091e" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 32985 } }
I20260812 06:16:47.746057 18799 raft_consensus.cc:385] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.746098 18799 raft_consensus.cc:740] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 523e41dea09849019d2868cfffb0091e, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.746224 18799 consensus_queue.cc:260] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [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: "523e41dea09849019d2868cfffb0091e" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 32985 } }
I20260812 06:16:47.746304 18799 raft_consensus.cc:399] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.746343 18799 raft_consensus.cc:493] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.746392 18799 raft_consensus.cc:3060] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.747181 18799 raft_consensus.cc:515] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "523e41dea09849019d2868cfffb0091e" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 32985 } }
I20260812 06:16:47.747329 18799 leader_election.cc:304] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [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: 523e41dea09849019d2868cfffb0091e; no voters: 
I20260812 06:16:47.747527 18799 leader_election.cc:290] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.747671 18802 raft_consensus.cc:2804] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.747871 18802 raft_consensus.cc:697] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 1 LEADER]: Becoming Leader. State: Replica: 523e41dea09849019d2868cfffb0091e, State: Running, Role: LEADER
I20260812 06:16:47.747884 18799 ts_tablet_manager.cc:1434] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:47.748052 18782 heartbeater.cc:499] Master 127.17.188.126:45663 was elected leader, sending a full tablet report...
I20260812 06:16:47.748075 18802 consensus_queue.cc:237] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [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: "523e41dea09849019d2868cfffb0091e" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 32985 } }
I20260812 06:16:47.749300 18549 catalog_manager.cc:5719] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e reported cstate change: term changed from 0 to 1, leader changed from <none> to 523e41dea09849019d2868cfffb0091e (127.17.188.65). New cstate: current_term: 1 leader_uuid: "523e41dea09849019d2868cfffb0091e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "523e41dea09849019d2868cfffb0091e" member_type: VOTER last_known_addr { host: "127.17.188.65" port: 32985 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:47.801503 18161 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.008s	sys 0.014s
I20260812 06:16:47.969763 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=23.023690
I20260812 06:16:48.132522 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.163s	user 0.116s	sys 0.039s Metrics: {"bytes_written":15999661,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":887,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43259,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"update_count":1950}
I20260812 06:16:48.133047 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling LogGCOp(ea6d87a4a08247a08ee713ff1beb7905): free 20743880 bytes of WAL
I20260812 06:16:48.133222 18666 log_reader.cc:385] T ea6d87a4a08247a08ee713ff1beb7905: removed 2 log segments from log reader
I20260812 06:16:48.133272 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000001 (ops 1-6)
I20260812 06:16:48.133304 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000002 (ops 7-11)
I20260812 06:16:48.136858 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: LogGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:48.137172 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:48.149039 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.149482 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:48.307111 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.157s	user 0.089s	sys 0.068s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24446413,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":597,"lbm_read_time_us":10932,"lbm_reads_lt_1ms":554,"lbm_write_time_us":27235,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":285,"threads_started":5,"update_count":2450}
I20260812 06:16:48.307721 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:48.359090 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.051s	user 0.044s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.359581 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:48.504783 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.145s	user 0.086s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754122,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":247,"lbm_read_time_us":9587,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24168,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.505288 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905): 20924070 bytes on disk
I20260812 06:16:48.505637 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.506042 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:48.559377 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.053s	user 0.042s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.559845 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:48.585160 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.022s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.585644 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:48.790930 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.205s	user 0.132s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":900,"lbm_read_time_us":13355,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32522,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:16:48.791498 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:48.852089 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.060s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.852530 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:48.867568 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.015s	user 0.010s	sys 0.004s 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:16:48.868096 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:49.018677 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.150s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":722,"lbm_read_time_us":12382,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26285,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:16:49.019275 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=11.118625
I20260812 06:16:49.050217 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.031s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12635684,"delete_count":0,"lbm_write_time_us":12802,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1540}
I20260812 06:16:49.050674 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.074771 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.024s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":4874,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:16:49.075241 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.084944 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3903,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.085497 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:49.229000 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.143s	user 0.126s	sys 0.012s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856766,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":779,"lbm_read_time_us":9453,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26975,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:49.229557 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=11.118625
I20260812 06:16:49.263047 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.033s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14027,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:49.263631 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.286654 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.023s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.287245 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.297000 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.297535 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:49.324131 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1392,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:49.324676 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling LogGCOp(ea6d87a4a08247a08ee713ff1beb7905): free 120553328 bytes of WAL
I20260812 06:16:49.324880 18666 log_reader.cc:385] T ea6d87a4a08247a08ee713ff1beb7905: removed 12 log segments from log reader
I20260812 06:16:49.324926 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000003 (ops 12-16)
I20260812 06:16:49.324954 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000004 (ops 17-20)
I20260812 06:16:49.324985 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000005 (ops 21-25)
I20260812 06:16:49.325026 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000006 (ops 26-30)
I20260812 06:16:49.325050 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000007 (ops 31-35)
I20260812 06:16:49.325067 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000008 (ops 36-40)
I20260812 06:16:49.325086 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000009 (ops 41-45)
I20260812 06:16:49.325117 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000010 (ops 46-50)
I20260812 06:16:49.325142 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000011 (ops 51-54)
I20260812 06:16:49.325163 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000012 (ops 55-59)
I20260812 06:16:49.325186 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000013 (ops 60-64)
I20260812 06:16:49.325207 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000014 (ops 65-69)
I20260812 06:16:49.350108 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: LogGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:49.350493 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.364295 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.364683 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.383497 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.019s	user 0.008s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.383924 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:49.584249 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.200s	user 0.135s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33061825,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":769,"lbm_read_time_us":14339,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35276,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:16:49.584787 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=15.087375
I20260812 06:16:49.633275 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.048s	user 0.028s	sys 0.018s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":16731,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:49.633813 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905): 447 bytes on disk
I20260812 06:16:49.634255 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"spinlock_wait_cycles":3456}
I20260812 06:16:49.634846 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.660023 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.025s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5995,"lbm_writes_lt_1ms":103,"mutex_wait_us":3,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.660452 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.670125 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.670562 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:49.869604 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.199s	user 0.123s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959172,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":359,"lbm_read_time_us":15392,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30107,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:16:49.870232 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=15.087375
I20260812 06:16:49.907253 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":16541,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:49.907716 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:49.919188 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.919569 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:50.078344 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.159s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856640,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":12360,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25973,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":2500}
I20260812 06:16:50.078840 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:50.128283 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.049s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18279,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.128751 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:50.138576 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.138964 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:50.301509 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.162s	user 0.097s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":791,"lbm_read_time_us":11341,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27207,"lbm_writes_lt_1ms":543,"mutex_wait_us":534,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:16:50.301972 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:50.355331 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.053s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17607,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.355865 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:50.370854 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.371344 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:50.546363 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.175s	user 0.118s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":13357,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29965,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:16:50.547253 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:50.596539 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.049s	user 0.010s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19635,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.597085 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:50.615312 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.018s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.615787 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:50.650609 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.035s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1184,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1467,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:50.651386 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling LogGCOp(ea6d87a4a08247a08ee713ff1beb7905): free 112692422 bytes of WAL
I20260812 06:16:50.651610 18666 log_reader.cc:385] T ea6d87a4a08247a08ee713ff1beb7905: removed 11 log segments from log reader
I20260812 06:16:50.651664 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000015 (ops 70-74)
I20260812 06:16:50.651701 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000016 (ops 75-79)
I20260812 06:16:50.651733 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000017 (ops 80-84)
I20260812 06:16:50.651768 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000018 (ops 85-89)
I20260812 06:16:50.651799 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000019 (ops 90-94)
I20260812 06:16:50.651830 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000020 (ops 95-99)
I20260812 06:16:50.651860 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000021 (ops 100-104)
I20260812 06:16:50.651890 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000022 (ops 105-109)
I20260812 06:16:50.651921 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000023 (ops 110-114)
I20260812 06:16:50.651950 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000024 (ops 115-119)
I20260812 06:16:50.651979 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000025 (ops 120-124)
I20260812 06:16:50.672024 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: LogGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:16:50.672464 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=3.181125
I20260812 06:16:50.692912 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:50.693324 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:50.706192 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5042,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.706619 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:50.942206 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.235s	user 0.155s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061707,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4287,"lbm_read_time_us":15683,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40242,"lbm_writes_lt_1ms":743,"mutex_wait_us":2985,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":71,"threads_started":1,"update_count":3500}
I20260812 06:16:50.942677 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=18.063937
I20260812 06:16:51.004513 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.061s	user 0.028s	sys 0.025s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25570,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:51.004928 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905): 447 bytes on disk
I20260812 06:16:51.005291 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.005775 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.015782 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.016230 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:51.205323 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.189s	user 0.127s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959068,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1070,"lbm_read_time_us":12784,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30603,"lbm_writes_lt_1ms":643,"mutex_wait_us":129,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:51.206054 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:51.251767 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.045s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19770,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.252307 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.272843 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.020s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.273269 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.282747 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.283187 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:51.469159 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.186s	user 0.106s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959186,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1073,"lbm_read_time_us":12349,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31674,"lbm_writes_lt_1ms":643,"mutex_wait_us":318,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:16:51.469627 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=15.087375
I20260812 06:16:51.514415 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.045s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":19216,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:51.514879 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.536079 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.018s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.536465 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.544940 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3211,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.545291 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:51.733647 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.188s	user 0.139s	sys 0.047s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":214,"lbm_read_time_us":13528,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30359,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:16:51.734269 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:51.799198 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.065s	user 0.044s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28460,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.799726 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=3.181125
I20260812 06:16:51.814790 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:51.815250 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:51.824611 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.825003 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:52.020709 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.196s	user 0.109s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":300,"lbm_read_time_us":13960,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31757,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:52.021279 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=16.079562
I20260812 06:16:52.065438 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.044s	user 0.028s	sys 0.011s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":18174,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:16:52.065953 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.196750
I20260812 06:16:52.077162 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.011s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3061,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:16:52.077625 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:52.087311 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.087791 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:52.116613 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushMRSOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1335,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:52.117421 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling LogGCOp(ea6d87a4a08247a08ee713ff1beb7905): free 136728493 bytes of WAL
I20260812 06:16:52.117663 18666 log_reader.cc:385] T ea6d87a4a08247a08ee713ff1beb7905: removed 13 log segments from log reader
I20260812 06:16:52.117719 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000026 (ops 125-129)
I20260812 06:16:52.117763 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000027 (ops 130-134)
I20260812 06:16:52.117802 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000028 (ops 135-139)
I20260812 06:16:52.117832 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000029 (ops 140-144)
I20260812 06:16:52.117869 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000030 (ops 145-149)
I20260812 06:16:52.117906 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000031 (ops 150-154)
I20260812 06:16:52.117944 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000032 (ops 155-159)
I20260812 06:16:52.117980 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000033 (ops 160-164)
I20260812 06:16:52.118042 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000034 (ops 165-169)
I20260812 06:16:52.118077 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000035 (ops 170-174)
I20260812 06:16:52.118114 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000036 (ops 175-179)
I20260812 06:16:52.118152 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000037 (ops 180-184)
I20260812 06:16:52.118188 18666 log.cc:1079] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: Deleting log segment in path: /tmp/dist-test-taskzpjwoe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402407965-18161-0/minicluster-data/ts-0-root/wals/ea6d87a4a08247a08ee713ff1beb7905/wal-000000038 (ops 185-189)
I20260812 06:16:52.145437 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: LogGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:52.145828 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905): 493 bytes on disk
I20260812 06:16:52.146319 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: UndoDeltaBlockGCOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.146860 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=3.181125
I20260812 06:16:52.158718 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4759050,"delete_count":0,"lbm_write_time_us":4663,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:16:52.159175 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=2.188937
I20260812 06:16:52.171144 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:16:52.171581 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=1.000000
I20260812 06:16:52.337985 18161 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.536s	user 1.608s	sys 0.179s
I20260812 06:16:52.384709 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: MajorDeltaCompactionOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.213s	user 0.123s	sys 0.088s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37164204,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16711,"lbm_reads_lt_1ms":871,"lbm_write_time_us":36633,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":4000}
I20260812 06:16:52.385167 18783 maintenance_manager.cc:419] P 523e41dea09849019d2868cfffb0091e: Scheduling FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905): perf score=14.095187
I20260812 06:16:52.413525 18161 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.000s	sys 0.000s
I20260812 06:16:52.413968 18161 tablet_server.cc:179] TabletServer@127.17.188.65:0 shutting down...
I20260812 06:16:52.472791 18666 maintenance_manager.cc:643] P 523e41dea09849019d2868cfffb0091e: FlushDeltaMemStoresOp(ea6d87a4a08247a08ee713ff1beb7905) complete. Timing: real 0.087s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.473328 18161 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:52.473558 18161 tablet_replica.cc:333] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e: stopping tablet replica
I20260812 06:16:52.473686 18161 raft_consensus.cc:2243] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.473829 18161 raft_consensus.cc:2272] T ea6d87a4a08247a08ee713ff1beb7905 P 523e41dea09849019d2868cfffb0091e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.488313 18161 tablet_server.cc:196] TabletServer@127.17.188.65:0 shutdown complete.
I20260812 06:16:52.491298 18161 master.cc:562] Master@127.17.188.126:45663 shutting down...
I20260812 06:16:52.494668 18161 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.494812 18161 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.494860 18161 tablet_replica.cc:333] T 00000000000000000000000000000000 P b0667c5149b2409fadf41ba8f31d39d9: stopping tablet replica
I20260812 06:16:52.506932 18161 master.cc:584] Master@127.17.188.126:45663 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4964 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10166 ms total)

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