[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:09.048013 25314 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.184.190:37231
I20260812 06:17:09.049116 25314 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:09.049782 25314 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.056799 25322 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:17:09.056900 25319 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:09.057065 25314 server_base.cc:1061] running on GCE node
W20260812 06:17:09.057117 25320 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:17:09.057623 25314 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.057765 25314 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:09.057811 25314 hybrid_clock.cc:648] HybridClock initialized: now 1786515429057808 us; error 0 us; skew 500 ppm
I20260812 06:17:09.059731 25314 webserver.cc:533] Webserver started at http://127.24.184.190:44207/ using document root <none> and password file <none>
I20260812 06:17:09.060315 25314 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.060375 25314 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.060668 25314 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.062379 25314 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/master-0-root/instance:
uuid: "fface3c8d7d84326a1b9eab94dadfaf8"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-pgkr"
I20260812 06:17:09.066090 25314 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:17:09.068497 25328 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.069533 25314 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:17:09.069682 25314 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/master-0-root
uuid: "fface3c8d7d84326a1b9eab94dadfaf8"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-pgkr"
I20260812 06:17:09.069787 25314 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:09.083949 25314 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.084618 25314 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:09.084821 25314 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.092573 25314 rpc_server.cc:307] RPC server started. Bound to: 127.24.184.190:37231
I20260812 06:17:09.092577 25391 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.184.190:37231 every 8 connection(s)
I20260812 06:17:09.095041 25392 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.100708 25392 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: Bootstrap starting.
I20260812 06:17:09.103248 25392 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.104270 25392 log.cc:826] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:09.106273 25392 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: No bootstrap required, opened a new log
I20260812 06:17:09.109352 25392 raft_consensus.cc:359] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER }
I20260812 06:17:09.109535 25392 raft_consensus.cc:385] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.109635 25392 raft_consensus.cc:740] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fface3c8d7d84326a1b9eab94dadfaf8, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.110313 25392 consensus_queue.cc:260] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [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: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER }
I20260812 06:17:09.110495 25392 raft_consensus.cc:399] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.110571 25392 raft_consensus.cc:493] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.110786 25392 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.111660 25392 raft_consensus.cc:515] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER }
I20260812 06:17:09.112165 25392 leader_election.cc:304] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [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: fface3c8d7d84326a1b9eab94dadfaf8; no voters: 
I20260812 06:17:09.112576 25392 leader_election.cc:290] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.112751 25395 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.113035 25395 raft_consensus.cc:697] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 1 LEADER]: Becoming Leader. State: Replica: fface3c8d7d84326a1b9eab94dadfaf8, State: Running, Role: LEADER
I20260812 06:17:09.113520 25395 consensus_queue.cc:237] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [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: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER }
I20260812 06:17:09.113798 25392 sys_catalog.cc:565] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:09.115541 25397 sys_catalog.cc:455] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader fface3c8d7d84326a1b9eab94dadfaf8. Latest consensus state: current_term: 1 leader_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER } }
I20260812 06:17:09.115574 25396 sys_catalog.cc:455] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fface3c8d7d84326a1b9eab94dadfaf8" member_type: VOTER } }
I20260812 06:17:09.115675 25396 sys_catalog.cc:458] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.115675 25397 sys_catalog.cc:458] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.116380 25314 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:09.118988 25411 catalog_manager.cc:1594] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:09.119076 25411 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:09.119189 25407 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:09.120045 25407 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:09.125213 25407 catalog_manager.cc:1383] Generated new cluster ID: 1428ae78f01240b4955a93d507d35ef0
I20260812 06:17:09.125319 25407 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:09.133402 25407 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:09.134337 25407 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:09.141626 25407 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: Generated new TSK 0
I20260812 06:17:09.142342 25407 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:09.149684 25314 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.153611 25415 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:09.153891 25418 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:17:09.153643 25416 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:17:09.154138 25314 server_base.cc:1061] running on GCE node
I20260812 06:17:09.154526 25314 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.154593 25314 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:09.154634 25314 hybrid_clock.cc:648] HybridClock initialized: now 1786515429154634 us; error 0 us; skew 500 ppm
I20260812 06:17:09.155692 25314 webserver.cc:533] Webserver started at http://127.24.184.129:42989/ using document root <none> and password file <none>
I20260812 06:17:09.155895 25314 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.155951 25314 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.156028 25314 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.156481 25314 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/instance:
uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-pgkr"
I20260812 06:17:09.158404 25314 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:09.159855 25424 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.160158 25314 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:09.160236 25314 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root
uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-pgkr"
I20260812 06:17:09.160334 25314 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:09.167752 25314 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.168206 25314 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.168733 25314 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:09.169600 25314 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:09.169651 25314 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.169724 25314 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:09.169763 25314 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.176699 25314 rpc_server.cc:307] RPC server started. Bound to: 127.24.184.129:41087
I20260812 06:17:09.176761 25495 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.184.129:41087 every 8 connection(s)
I20260812 06:17:09.187556 25496 heartbeater.cc:344] Connected to a master server at 127.24.184.190:37231
I20260812 06:17:09.187842 25496 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:09.188331 25496 heartbeater.cc:507] Master 127.24.184.190:37231 requested a full tablet report, sending...
I20260812 06:17:09.189859 25348 ts_manager.cc:194] Registered new tserver with Master: c7581b4dabbf4b588d6c70e98fbf9a9d (127.24.184.129:41087)
I20260812 06:17:09.190007 25314 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012437638s
I20260812 06:17:09.191390 25348 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59920
I20260812 06:17:09.201196 25348 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59934:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:09.215904 25453 tablet_service.cc:1511] Processing CreateTablet for tablet 95b2e1a4f32a4a05966df3c548004f09 (DEFAULT_TABLE table=heavy-update-compaction-test [id=14fcbba7c606400a9fe1610c23237b2d]), partition=
I20260812 06:17:09.216408 25453 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 95b2e1a4f32a4a05966df3c548004f09. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.218705 25509 tablet_bootstrap.cc:492] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Bootstrap starting.
I20260812 06:17:09.219769 25509 tablet_bootstrap.cc:654] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.220920 25509 tablet_bootstrap.cc:492] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: No bootstrap required, opened a new log
I20260812 06:17:09.221031 25509 ts_tablet_manager.cc:1403] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:09.221467 25509 raft_consensus.cc:359] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 41087 } }
I20260812 06:17:09.221576 25509 raft_consensus.cc:385] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.221601 25509 raft_consensus.cc:740] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c7581b4dabbf4b588d6c70e98fbf9a9d, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.221791 25509 consensus_queue.cc:260] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [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: "c7581b4dabbf4b588d6c70e98fbf9a9d" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 41087 } }
I20260812 06:17:09.221889 25509 raft_consensus.cc:399] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.221949 25509 raft_consensus.cc:493] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.222026 25509 raft_consensus.cc:3060] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.223013 25509 raft_consensus.cc:515] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 41087 } }
I20260812 06:17:09.223174 25509 leader_election.cc:304] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [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: c7581b4dabbf4b588d6c70e98fbf9a9d; no voters: 
I20260812 06:17:09.223419 25509 leader_election.cc:290] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.223538 25511 raft_consensus.cc:2804] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.223726 25511 raft_consensus.cc:697] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 1 LEADER]: Becoming Leader. State: Replica: c7581b4dabbf4b588d6c70e98fbf9a9d, State: Running, Role: LEADER
I20260812 06:17:09.223803 25509 ts_tablet_manager.cc:1434] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:09.223940 25511 consensus_queue.cc:237] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [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: "c7581b4dabbf4b588d6c70e98fbf9a9d" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 41087 } }
I20260812 06:17:09.224068 25496 heartbeater.cc:499] Master 127.24.184.190:37231 was elected leader, sending a full tablet report...
I20260812 06:17:09.226692 25348 catalog_manager.cc:5719] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d reported cstate change: term changed from 0 to 1, leader changed from <none> to c7581b4dabbf4b588d6c70e98fbf9a9d (127.24.184.129). New cstate: current_term: 1 leader_uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7581b4dabbf4b588d6c70e98fbf9a9d" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 41087 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.297933 25314 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.020s	sys 0.009s
I20260812 06:17:09.428169 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09): perf score=15.086190
I20260812 06:17:09.598901 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.170s	user 0.129s	sys 0.039s Metrics: {"bytes_written":13497182,"cfile_init":1,"compiler_manager_pool.queue_time_us":226,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1185,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41879,"lbm_writes_lt_1ms":696,"mutex_wait_us":2429,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":113024,"thread_start_us":145,"threads_started":1,"update_count":1645}
I20260812 06:17:09.600103 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling LogGCOp(95b2e1a4f32a4a05966df3c548004f09): free 20743880 bytes of WAL
I20260812 06:17:09.600414 25430 log_reader.cc:385] T 95b2e1a4f32a4a05966df3c548004f09: removed 2 log segments from log reader
I20260812 06:17:09.600479 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000001 (ops 1-6)
I20260812 06:17:09.600530 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000002 (ops 7-11)
I20260812 06:17:09.606108 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: LogGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:09.606518 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09): 12719216 bytes on disk
I20260812 06:17:09.607183 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.607824 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=5.165500
I20260812 06:17:09.626268 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6359000,"delete_count":0,"lbm_write_time_us":7630,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:17:09.626839 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:09.777513 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.150s	user 0.122s	sys 0.029s Metrics: {"cfile_cache_miss":516,"cfile_cache_miss_bytes":24118304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":756,"lbm_read_time_us":10051,"lbm_reads_lt_1ms":548,"lbm_write_time_us":30048,"lbm_writes_lt_1ms":527,"peak_mem_usage":60378572,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":290,"threads_started":5,"update_count":2420}
I20260812 06:17:09.777997 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=11.118625
I20260812 06:17:09.819243 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.041s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12553642,"delete_count":0,"lbm_write_time_us":16579,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:17:09.819804 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:09.926440 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.106s	user 0.094s	sys 0.012s Metrics: {"cfile_cache_miss":337,"cfile_cache_miss_bytes":16815898,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":715,"lbm_read_time_us":6284,"lbm_reads_lt_1ms":369,"lbm_write_time_us":21097,"lbm_writes_lt_1ms":349,"mutex_wait_us":96,"peak_mem_usage":38508966,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":1530}
I20260812 06:17:09.927069 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:09.967687 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.040s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16553,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.968184 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:09.979979 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.980540 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:10.109690 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.129s	user 0.096s	sys 0.033s 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":192,"lbm_read_time_us":9512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23953,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:17:10.110327 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:10.168097 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.058s	user 0.024s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18606,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.168767 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:10.180029 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.180508 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:10.330684 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.150s	user 0.126s	sys 0.023s 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":808,"lbm_read_time_us":11598,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23673,"lbm_writes_lt_1ms":443,"mutex_wait_us":282,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:17:10.331334 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:10.377851 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.046s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15675,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.378356 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:10.389516 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.390246 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:10.516059 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.126s	user 0.094s	sys 0.032s 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":163,"lbm_read_time_us":8009,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26288,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:10.516570 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:10.562453 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.046s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22355,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.562989 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:10.573453 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.574091 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:10.706766 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.132s	user 0.116s	sys 0.016s 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":901,"lbm_read_time_us":9970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24661,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:17:10.707356 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:10.756443 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.049s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16138,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.757135 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:10.768339 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.768814 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:10.924497 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.156s	user 0.084s	sys 0.071s 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":679,"lbm_read_time_us":12128,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23986,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:10.925163 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:10.957599 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14170,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.958238 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:10.971611 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.972147 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:11.009258 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.037s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":449,"dirs.run_wall_time_us":1922,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2175,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:11.010210 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling LogGCOp(95b2e1a4f32a4a05966df3c548004f09): free 124257257 bytes of WAL
I20260812 06:17:11.010492 25430 log_reader.cc:385] T 95b2e1a4f32a4a05966df3c548004f09: removed 12 log segments from log reader
I20260812 06:17:11.010579 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000003 (ops 12-16)
I20260812 06:17:11.010687 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000004 (ops 17-21)
I20260812 06:17:11.010735 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000005 (ops 22-26)
I20260812 06:17:11.010764 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000006 (ops 27-31)
I20260812 06:17:11.010793 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000007 (ops 32-36)
I20260812 06:17:11.010821 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000008 (ops 37-41)
I20260812 06:17:11.010849 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000009 (ops 42-46)
I20260812 06:17:11.010876 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000010 (ops 47-50)
I20260812 06:17:11.010906 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000011 (ops 51-55)
I20260812 06:17:11.010962 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000012 (ops 56-60)
I20260812 06:17:11.010991 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000013 (ops 61-65)
I20260812 06:17:11.011053 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000014 (ops 66-70)
I20260812 06:17:11.042280 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: LogGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.032s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:17:11.042876 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09): 483 bytes on disk
I20260812 06:17:11.043339 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.043854 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=5.165500
I20260812 06:17:11.079157 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.035s	user 0.027s	sys 0.007s Metrics: {"bytes_written":7220497,"delete_count":0,"lbm_write_time_us":9836,"lbm_writes_lt_1ms":179,"reinsert_count":0,"update_count":880}
I20260812 06:17:11.083007 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:11.297345 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.214s	user 0.136s	sys 0.068s Metrics: {"cfile_cache_miss":609,"cfile_cache_miss_bytes":27892640,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":5052,"lbm_read_time_us":15540,"lbm_reads_lt_1ms":645,"lbm_write_time_us":33492,"lbm_writes_lt_1ms":619,"mutex_wait_us":2026,"peak_mem_usage":72476864,"reinsert_count":0,"thread_start_us":84,"threads_started":1,"update_count":2880}
I20260812 06:17:11.297911 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=15.087375
I20260812 06:17:11.357893 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.060s	user 0.042s	sys 0.015s Metrics: {"bytes_written":17394485,"delete_count":0,"lbm_write_time_us":22401,"lbm_writes_lt_1ms":427,"reinsert_count":0,"update_count":2120}
I20260812 06:17:11.358495 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:11.369464 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.370126 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:11.548278 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.178s	user 0.114s	sys 0.064s Metrics: {"cfile_cache_miss":556,"cfile_cache_miss_bytes":25759272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":15652,"lbm_reads_lt_1ms":596,"lbm_write_time_us":28941,"lbm_writes_lt_1ms":567,"mutex_wait_us":314,"peak_mem_usage":66181508,"reinsert_count":0,"spinlock_wait_cycles":49792,"update_count":2620}
I20260812 06:17:11.549070 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:11.585182 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15573,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.585698 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:11.603498 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.604142 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:11.742745 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.138s	user 0.110s	sys 0.028s 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":383,"lbm_read_time_us":8088,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26993,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.743407 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:11.788012 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.044s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15345,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.788463 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:11.799088 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.799817 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:11.931165 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.131s	user 0.096s	sys 0.035s 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":1046,"lbm_read_time_us":9116,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25479,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.931743 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:11.968600 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.037s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15353,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.969130 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:11.986436 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.987053 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:12.116050 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.129s	user 0.086s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":7623,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26272,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.116751 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=11.118625
I20260812 06:17:12.167378 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.050s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22391,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.167972 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:12.180383 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.180835 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:12.190073 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3583,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.190521 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:12.357618 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.167s	user 0.132s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":958,"lbm_read_time_us":13210,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31674,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.358341 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=11.118625
I20260812 06:17:12.404814 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.046s	user 0.026s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15750,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.405421 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:12.420109 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.420594 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:12.447955 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.027s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1526,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1411,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:12.448706 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling LogGCOp(95b2e1a4f32a4a05966df3c548004f09): free 121006443 bytes of WAL
I20260812 06:17:12.448978 25430 log_reader.cc:385] T 95b2e1a4f32a4a05966df3c548004f09: removed 12 log segments from log reader
I20260812 06:17:12.449047 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000015 (ops 71-75)
I20260812 06:17:12.449105 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000016 (ops 76-80)
I20260812 06:17:12.449141 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000017 (ops 81-85)
I20260812 06:17:12.449174 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000018 (ops 86-90)
I20260812 06:17:12.449216 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000019 (ops 91-95)
I20260812 06:17:12.449254 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000020 (ops 96-100)
I20260812 06:17:12.449290 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000021 (ops 101-104)
I20260812 06:17:12.449326 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000022 (ops 105-109)
I20260812 06:17:12.449364 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000023 (ops 110-114)
I20260812 06:17:12.449401 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000024 (ops 115-119)
I20260812 06:17:12.449437 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000025 (ops 120-124)
I20260812 06:17:12.449473 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000026 (ops 125-129)
I20260812 06:17:12.477632 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: LogGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:12.478210 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=3.181125
I20260812 06:17:12.500350 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.022s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7084,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:12.500864 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:12.510517 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3597,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.511119 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:12.724866 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.214s	user 0.134s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":282,"lbm_read_time_us":13412,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37076,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":71040,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:12.726181 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=14.095187
I20260812 06:17:12.771541 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.045s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20538,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.772056 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:12.915915 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.144s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":209,"lbm_read_time_us":10957,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23681,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:17:12.916501 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=11.118625
I20260812 06:17:12.955130 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.038s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16909,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.955597 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09): 462 bytes on disk
I20260812 06:17:12.956004 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.956490 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:12.968268 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.968701 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.094453 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.126s	user 0.109s	sys 0.016s 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":485,"lbm_read_time_us":8921,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25064,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:13.095098 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:13.138033 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.043s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.138592 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:13.149688 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.150575 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.297546 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.147s	user 0.111s	sys 0.033s 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":428,"lbm_read_time_us":9688,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25295,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":67584,"update_count":2000}
I20260812 06:17:13.299741 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:13.343863 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.044s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14940,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.344398 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:13.355235 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.356006 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.488862 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.133s	user 0.106s	sys 0.026s 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":353,"lbm_read_time_us":9185,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26803,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:13.489558 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:13.535907 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.046s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15389,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.536566 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:13.552628 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.553234 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.701921 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.148s	user 0.121s	sys 0.028s 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":288,"lbm_read_time_us":11486,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25954,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:13.702685 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:13.736725 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.034s	user 0.014s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.737231 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:13.751789 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.752388 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.883682 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.131s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26591,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:13.884522 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=10.126437
I20260812 06:17:13.928546 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.044s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18662,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.929196 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:13.942039 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.942674 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:13.975868 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushMRSOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1255,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2320,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.976562 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling LogGCOp(95b2e1a4f32a4a05966df3c548004f09): free 124257508 bytes of WAL
I20260812 06:17:13.976797 25430 log_reader.cc:385] T 95b2e1a4f32a4a05966df3c548004f09: removed 12 log segments from log reader
I20260812 06:17:13.976868 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000027 (ops 130-134)
I20260812 06:17:13.976948 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000028 (ops 135-139)
I20260812 06:17:13.977010 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000029 (ops 140-144)
I20260812 06:17:13.977061 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000030 (ops 145-149)
I20260812 06:17:13.977123 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000031 (ops 150-154)
I20260812 06:17:13.977169 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000032 (ops 155-158)
I20260812 06:17:13.977212 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000033 (ops 159-163)
I20260812 06:17:13.977257 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000034 (ops 164-168)
I20260812 06:17:13.977299 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000035 (ops 169-173)
I20260812 06:17:13.977344 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000036 (ops 174-178)
I20260812 06:17:13.977386 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000037 (ops 179-183)
I20260812 06:17:13.977430 25430 log.cc:1079] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/95b2e1a4f32a4a05966df3c548004f09/wal-000000038 (ops 184-188)
I20260812 06:17:14.004647 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: LogGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:14.005116 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09): 463 bytes on disk
I20260812 06:17:14.005671 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: UndoDeltaBlockGCOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.006587 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=4.173312
I20260812 06:17:14.028915 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.022s	user 0.015s	sys 0.005s Metrics: {"bytes_written":6358990,"delete_count":0,"lbm_write_time_us":9049,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:17:14.029552 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:14.040113 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":3225,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:17:14.040711 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:14.218097 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.177s	user 0.133s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877284,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":329,"lbm_read_time_us":12825,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36832,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":64,"threads_started":1,"update_count":3000}
I20260812 06:17:14.218606 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=14.095187
I20260812 06:17:14.273536 25314 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.975s	user 1.800s	sys 0.142s
I20260812 06:17:14.277292 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.058s	user 0.034s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25139,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.277889 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09): perf score=2.188937
I20260812 06:17:14.288990 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: FlushDeltaMemStoresOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.289675 25497 maintenance_manager.cc:419] P c7581b4dabbf4b588d6c70e98fbf9a9d: Scheduling MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09): perf score=1.000000
I20260812 06:17:14.323005 25314 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.003s	sys 0.000s
I20260812 06:17:14.323704 25314 tablet_server.cc:179] TabletServer@127.24.184.129:0 shutting down...
I20260812 06:17:14.406759 25430 maintenance_manager.cc:643] P c7581b4dabbf4b588d6c70e98fbf9a9d: MajorDeltaCompactionOp(95b2e1a4f32a4a05966df3c548004f09) complete. Timing: real 0.117s	user 0.083s	sys 0.034s Metrics: {"cfile_cache_hit":344,"cfile_cache_hit_bytes":14072141,"cfile_cache_miss":188,"cfile_cache_miss_bytes":10702548,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":743,"lbm_read_time_us":4485,"lbm_reads_lt_1ms":220,"lbm_write_time_us":26024,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:14.407478 25314 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.407923 25314 tablet_replica.cc:333] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d: stopping tablet replica
I20260812 06:17:14.408169 25314 raft_consensus.cc:2243] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.408401 25314 raft_consensus.cc:2272] T 95b2e1a4f32a4a05966df3c548004f09 P c7581b4dabbf4b588d6c70e98fbf9a9d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.424137 25314 tablet_server.cc:196] TabletServer@127.24.184.129:0 shutdown complete.
I20260812 06:17:14.453056 25314 master.cc:562] Master@127.24.184.190:37231 shutting down...
I20260812 06:17:14.457402 25314 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.457605 25314 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.457684 25314 tablet_replica.cc:333] T 00000000000000000000000000000000 P fface3c8d7d84326a1b9eab94dadfaf8: stopping tablet replica
I20260812 06:17:14.469893 25314 master.cc:584] Master@127.24.184.190:37231 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5513 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:14.561317 25314 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.184.190:46107
I20260812 06:17:14.561723 25314 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.563824 25535 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:17:14.563956 25533 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:14.564018 25532 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.564224 25314 server_base.cc:1061] running on GCE node
I20260812 06:17:14.564404 25314 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.564463 25314 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:14.564487 25314 hybrid_clock.cc:648] HybridClock initialized: now 1786515434564486 us; error 0 us; skew 500 ppm
I20260812 06:17:14.565449 25314 webserver.cc:533] Webserver started at http://127.24.184.190:44781/ using document root <none> and password file <none>
I20260812 06:17:14.565662 25314 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.565723 25314 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.565799 25314 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.566198 25314 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/master-0-root/instance:
uuid: "6352b8d2ede34d4db1ebd61483e59363"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-pgkr"
I20260812 06:17:14.567790 25314 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:14.568722 25541 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.568974 25314 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:14.569067 25314 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/master-0-root
uuid: "6352b8d2ede34d4db1ebd61483e59363"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-pgkr"
I20260812 06:17:14.569162 25314 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:14.581211 25314 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.581640 25314 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.586225 25314 rpc_server.cc:307] RPC server started. Bound to: 127.24.184.190:46107
I20260812 06:17:14.589382 25597 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:14.595093 25597 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363: Bootstrap starting.
I20260812 06:17:14.602672 25596 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.184.190:46107 every 8 connection(s)
I20260812 06:17:14.603458 25597 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.605073 25597 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363: No bootstrap required, opened a new log
I20260812 06:17:14.605789 25597 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER }
I20260812 06:17:14.605917 25597 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.605943 25597 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6352b8d2ede34d4db1ebd61483e59363, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.606189 25597 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [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: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER }
I20260812 06:17:14.606449 25597 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.606596 25597 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.606731 25597 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.607646 25597 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER }
I20260812 06:17:14.607817 25597 leader_election.cc:304] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [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: 6352b8d2ede34d4db1ebd61483e59363; no voters: 
I20260812 06:17:14.608064 25597 leader_election.cc:290] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.608259 25600 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.608493 25600 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 1 LEADER]: Becoming Leader. State: Replica: 6352b8d2ede34d4db1ebd61483e59363, State: Running, Role: LEADER
I20260812 06:17:14.608652 25600 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [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: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER }
I20260812 06:17:14.608767 25597 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:14.609107 25601 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6352b8d2ede34d4db1ebd61483e59363" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER } }
I20260812 06:17:14.609217 25601 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.609126 25602 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6352b8d2ede34d4db1ebd61483e59363. Latest consensus state: current_term: 1 leader_uuid: "6352b8d2ede34d4db1ebd61483e59363" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6352b8d2ede34d4db1ebd61483e59363" member_type: VOTER } }
I20260812 06:17:14.609337 25602 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.610921 25604 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:14.611063 25314 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:14.612005 25604 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:14.614199 25604 catalog_manager.cc:1383] Generated new cluster ID: 8cc1a3924ee647a38651ff35d4cf91d4
I20260812 06:17:14.614264 25604 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:14.625264 25604 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:14.625921 25604 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:14.633401 25604 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363: Generated new TSK 0
I20260812 06:17:14.633683 25604 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:14.643698 25314 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.645859 25623 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.645828 25314 server_base.cc:1061] running on GCE node
W20260812 06:17:14.645826 25621 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:14.645826 25620 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.646487 25314 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.646556 25314 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:14.646576 25314 hybrid_clock.cc:648] HybridClock initialized: now 1786515434646577 us; error 0 us; skew 500 ppm
I20260812 06:17:14.647549 25314 webserver.cc:533] Webserver started at http://127.24.184.129:45183/ using document root <none> and password file <none>
I20260812 06:17:14.647697 25314 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.647744 25314 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.647809 25314 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.648188 25314 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/instance:
uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-pgkr"
I20260812 06:17:14.649686 25314 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:14.650579 25630 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.650857 25314 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:14.650923 25314 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root
uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-pgkr"
I20260812 06:17:14.651031 25314 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:14.660519 25314 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.660943 25314 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.661275 25314 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:14.661755 25314 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:14.661816 25314 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.661877 25314 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:14.661911 25314 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.666208 25314 rpc_server.cc:307] RPC server started. Bound to: 127.24.184.129:37193
I20260812 06:17:14.666951 25706 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.184.129:37193 every 8 connection(s)
I20260812 06:17:14.674583 25707 heartbeater.cc:344] Connected to a master server at 127.24.184.190:46107
I20260812 06:17:14.674738 25707 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:14.674966 25707 heartbeater.cc:507] Master 127.24.184.190:46107 requested a full tablet report, sending...
I20260812 06:17:14.675583 25558 ts_manager.cc:194] Registered new tserver with Master: 5028c21e35dd4f14bea1c89e0a7fa4ea (127.24.184.129:37193)
I20260812 06:17:14.675894 25314 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008842624s
I20260812 06:17:14.676343 25558 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41620
I20260812 06:17:14.682600 25558 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41630:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:14.691102 25663 tablet_service.cc:1511] Processing CreateTablet for tablet 9fe5e6a6557c4fd7adcbefc7b91532c8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=04bfa9ab13934dafb8f827d816d672f0]), partition=
I20260812 06:17:14.691387 25663 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9fe5e6a6557c4fd7adcbefc7b91532c8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:14.693527 25725 tablet_bootstrap.cc:492] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Bootstrap starting.
I20260812 06:17:14.694343 25725 tablet_bootstrap.cc:654] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.695428 25725 tablet_bootstrap.cc:492] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: No bootstrap required, opened a new log
I20260812 06:17:14.695514 25725 ts_tablet_manager.cc:1403] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:17:14.695895 25725 raft_consensus.cc:359] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 37193 } }
I20260812 06:17:14.695981 25725 raft_consensus.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.696003 25725 raft_consensus.cc:740] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5028c21e35dd4f14bea1c89e0a7fa4ea, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.696141 25725 consensus_queue.cc:260] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [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: "5028c21e35dd4f14bea1c89e0a7fa4ea" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 37193 } }
I20260812 06:17:14.696285 25725 raft_consensus.cc:399] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.696331 25725 raft_consensus.cc:493] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.696385 25725 raft_consensus.cc:3060] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.697292 25725 raft_consensus.cc:515] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 37193 } }
I20260812 06:17:14.697444 25725 leader_election.cc:304] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [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: 5028c21e35dd4f14bea1c89e0a7fa4ea; no voters: 
I20260812 06:17:14.697660 25725 leader_election.cc:290] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.697795 25727 raft_consensus.cc:2804] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.698011 25725 ts_tablet_manager.cc:1434] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:14.698033 25707 heartbeater.cc:499] Master 127.24.184.190:46107 was elected leader, sending a full tablet report...
I20260812 06:17:14.698036 25727 raft_consensus.cc:697] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 1 LEADER]: Becoming Leader. State: Replica: 5028c21e35dd4f14bea1c89e0a7fa4ea, State: Running, Role: LEADER
I20260812 06:17:14.698463 25727 consensus_queue.cc:237] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [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: "5028c21e35dd4f14bea1c89e0a7fa4ea" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 37193 } }
I20260812 06:17:14.699817 25558 catalog_manager.cc:5719] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea reported cstate change: term changed from 0 to 1, leader changed from <none> to 5028c21e35dd4f14bea1c89e0a7fa4ea (127.24.184.129). New cstate: current_term: 1 leader_uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5028c21e35dd4f14bea1c89e0a7fa4ea" member_type: VOTER last_known_addr { host: "127.24.184.129" port: 37193 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:14.762466 25314 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.018s	sys 0.004s
I20260812 06:17:14.917541 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=19.054940
I20260812 06:17:15.069859 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.152s	user 0.102s	sys 0.043s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":409,"dirs.run_wall_time_us":1026,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40561,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:15.070719 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): free 20743880 bytes of WAL
I20260812 06:17:15.070968 25637 log_reader.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8: removed 2 log segments from log reader
I20260812 06:17:15.071017 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000001 (ops 1-6)
I20260812 06:17:15.071049 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000002 (ops 7-11)
I20260812 06:17:15.075438 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:15.075858 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): 16411395 bytes on disk
I20260812 06:17:15.076321 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.076864 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:15.092092 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.092696 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:15.244652 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.152s	user 0.091s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":12212,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24841,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":378,"threads_started":5,"update_count":2000}
I20260812 06:17:15.247103 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=11.118625
I20260812 06:17:15.297343 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.050s	user 0.022s	sys 0.021s Metrics: {"bytes_written":14112552,"delete_count":0,"lbm_write_time_us":20485,"lbm_writes_lt_1ms":347,"mutex_wait_us":2167,"reinsert_count":0,"update_count":1720}
I20260812 06:17:15.298079 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.196750
I20260812 06:17:15.309662 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.011s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2707809,"delete_count":0,"lbm_write_time_us":2829,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:17:15.310293 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:15.320779 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.321213 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:15.510808 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.189s	user 0.130s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774766,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":149,"lbm_read_time_us":14844,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29459,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:15.511430 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:15.562829 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.051s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21192,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.563287 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:15.718772 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.155s	user 0.096s	sys 0.059s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":325,"lbm_read_time_us":11077,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24223,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.719372 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:15.769585 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.050s	user 0.016s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21351,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:15.770081 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:15.785348 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.785943 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:15.966662 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.181s	user 0.106s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":10964,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29572,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:17:15.967144 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:16.018570 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23153,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.019186 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:16.032547 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.032982 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:16.197257 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.164s	user 0.113s	sys 0.043s 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":364,"lbm_read_time_us":12888,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30217,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24704,"update_count":2500}
I20260812 06:17:16.197919 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=11.118625
I20260812 06:17:16.233600 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.035s	user 0.010s	sys 0.022s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15717,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:16.234135 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:16.253513 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.019s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.254029 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:16.293331 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.039s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1378,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1522,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:16.294183 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=3.181125
I20260812 06:17:16.314116 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7636,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:16.314704 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): free 108535453 bytes of WAL
I20260812 06:17:16.314935 25637 log_reader.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8: removed 11 log segments from log reader
I20260812 06:17:16.314989 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000003 (ops 12-16)
I20260812 06:17:16.315048 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000004 (ops 17-20)
I20260812 06:17:16.315099 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000005 (ops 21-25)
I20260812 06:17:16.315140 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000006 (ops 26-30)
I20260812 06:17:16.315192 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000007 (ops 31-34)
I20260812 06:17:16.315250 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000008 (ops 35-39)
I20260812 06:17:16.315297 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000009 (ops 40-44)
I20260812 06:17:16.315330 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000010 (ops 45-49)
I20260812 06:17:16.315374 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000011 (ops 50-54)
I20260812 06:17:16.315423 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000012 (ops 55-59)
I20260812 06:17:16.315467 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000013 (ops 60-64)
I20260812 06:17:16.338366 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:16.338850 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): 447 bytes on disk
I20260812 06:17:16.339375 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.339852 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:16.364584 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.025s	user 0.007s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.365123 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): free 11564875 bytes of WAL
I20260812 06:17:16.365336 25637 log_reader.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8: removed 1 log segments from log reader
I20260812 06:17:16.365377 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000014 (ops 65-68)
I20260812 06:17:16.367817 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:16.368105 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:16.378839 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.379258 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:16.635066 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.256s	user 0.163s	sys 0.081s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":867,"lbm_read_time_us":17759,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38951,"lbm_writes_lt_1ms":743,"mutex_wait_us":350,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:17:16.635978 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=18.063937
I20260812 06:17:16.710913 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.075s	user 0.036s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28072,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:16.711494 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:16.723783 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.724385 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:16.930539 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.206s	user 0.117s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":802,"lbm_read_time_us":16303,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33712,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":3000}
I20260812 06:17:16.931295 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=16.079562
I20260812 06:17:16.997447 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.066s	user 0.027s	sys 0.021s Metrics: {"bytes_written":17845756,"delete_count":0,"lbm_write_time_us":22737,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:17:16.997967 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=5.165500
I20260812 06:17:17.017274 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6769240,"delete_count":0,"lbm_write_time_us":8227,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:17:17.017763 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:17.227327 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.209s	user 0.140s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877118,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":448,"lbm_read_time_us":14828,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33276,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:17:17.228363 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=16.079562
I20260812 06:17:17.277300 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":17681652,"delete_count":0,"lbm_write_time_us":21166,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:17:17.277745 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:17.302186 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":4878,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:17.302759 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:17.316485 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.316978 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:17.534436 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.217s	user 0.153s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877191,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":244,"lbm_read_time_us":18833,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32506,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":3000}
I20260812 06:17:17.535214 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=15.087375
I20260812 06:17:17.585292 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.050s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:17.585767 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:17.603513 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.017s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4763,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.603973 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:17.618494 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.619120 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:17.814567 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.195s	user 0.122s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":508,"lbm_read_time_us":14075,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33533,"lbm_writes_lt_1ms":643,"mutex_wait_us":276,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:17:17.815765 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:17.862977 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.047s	user 0.029s	sys 0.018s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20562,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.863662 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:17.877521 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.877986 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:17.908948 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1312,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:17.909695 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): free 124710315 bytes of WAL
I20260812 06:17:17.909998 25637 log_reader.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8: removed 12 log segments from log reader
I20260812 06:17:17.910097 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000015 (ops 69-73)
I20260812 06:17:17.910295 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000016 (ops 74-78)
I20260812 06:17:17.910395 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000017 (ops 79-83)
I20260812 06:17:17.910441 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000018 (ops 84-88)
I20260812 06:17:17.910477 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000019 (ops 89-93)
I20260812 06:17:17.910512 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000020 (ops 94-98)
I20260812 06:17:17.910584 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000021 (ops 99-103)
I20260812 06:17:17.910670 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000022 (ops 104-109)
I20260812 06:17:17.910722 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000023 (ops 110-114)
I20260812 06:17:17.910760 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000024 (ops 115-119)
I20260812 06:17:17.910797 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000025 (ops 120-124)
I20260812 06:17:17.910835 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000026 (ops 125-128)
I20260812 06:17:17.941383 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.031s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:17:17.942905 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): 482 bytes on disk
I20260812 06:17:17.943396 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) 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}
I20260812 06:17:17.943928 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=4.173312
I20260812 06:17:17.961746 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":5866706,"delete_count":0,"lbm_write_time_us":7357,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:17:17.962337 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.196750
I20260812 06:17:17.972343 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":3572,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:17:17.972788 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:18.205750 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.233s	user 0.139s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979714,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":170,"lbm_read_time_us":16123,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41208,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:17:18.207330 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=18.063937
I20260812 06:17:18.269774 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.062s	user 0.042s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28472,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:18.270247 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:18.284581 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.285076 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:18.448560 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.163s	user 0.127s	sys 0.036s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":174,"lbm_read_time_us":12654,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34654,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":3000}
I20260812 06:17:18.449235 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:18.497757 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.498284 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:18.513196 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.513774 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:18.694155 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.180s	user 0.139s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"dirs.run_cpu_time_us":1888,"dirs.run_wall_time_us":7010,"lbm_read_time_us":9527,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32946,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:17:18.694896 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:18.744923 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.050s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20118,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.745555 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:18.894779 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.149s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":926,"lbm_read_time_us":10937,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23143,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":78720,"update_count":2000}
I20260812 06:17:18.895372 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:18.951212 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.056s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.951831 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:18.964329 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.964828 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.145002 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.180s	user 0.129s	sys 0.042s 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":294,"lbm_read_time_us":12581,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29904,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:19.145569 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:19.203378 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.058s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.203990 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:19.216326 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.216970 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.391579 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.174s	user 0.127s	sys 0.036s 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":760,"lbm_read_time_us":11180,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31950,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:17:19.392212 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=14.095187
I20260812 06:17:19.447471 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.055s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24982,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.447997 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=2.188937
I20260812 06:17:19.464187 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.464804 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.495714 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushMRSOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1528,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2014,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:19.496516 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): free 133024651 bytes of WAL
I20260812 06:17:19.496812 25637 log_reader.cc:385] T 9fe5e6a6557c4fd7adcbefc7b91532c8: removed 13 log segments from log reader
I20260812 06:17:19.496882 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000027 (ops 129-133)
I20260812 06:17:19.496935 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000028 (ops 134-138)
I20260812 06:17:19.496990 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000029 (ops 139-143)
I20260812 06:17:19.497030 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000030 (ops 144-148)
I20260812 06:17:19.497071 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000031 (ops 149-153)
I20260812 06:17:19.497110 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000032 (ops 154-158)
I20260812 06:17:19.497150 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000033 (ops 159-162)
I20260812 06:17:19.497189 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000034 (ops 163-167)
I20260812 06:17:19.497228 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000035 (ops 168-172)
I20260812 06:17:19.497267 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000036 (ops 173-177)
I20260812 06:17:19.497313 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000037 (ops 178-182)
I20260812 06:17:19.497349 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000038 (ops 183-187)
I20260812 06:17:19.497390 25637 log.cc:1079] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: Deleting log segment in path: /tmp/dist-test-taskpgkBto/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429037070-25314-0/minicluster-data/ts-0-root/wals/9fe5e6a6557c4fd7adcbefc7b91532c8/wal-000000039 (ops 188-192)
I20260812 06:17:19.528012 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: LogGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:19.528508 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=5.165500
I20260812 06:17:19.563473 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.035s	user 0.015s	sys 0.019s Metrics: {"bytes_written":6769231,"delete_count":0,"lbm_write_time_us":9225,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:17:19.564199 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8): 493 bytes on disk
I20260812 06:17:19.564883 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: UndoDeltaBlockGCOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.565531 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.571040 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.005s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1436027,"delete_count":0,"lbm_write_time_us":1606,"lbm_writes_lt_1ms":38,"reinsert_count":0,"update_count":175}
I20260812 06:17:19.571430 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.728752 25314 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.966s	user 1.850s	sys 0.142s
I20260812 06:17:19.788477 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.217s	user 0.170s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16725,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37593,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:17:19.789052 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=10.126437
I20260812 06:17:19.816277 25314 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.003s	sys 0.000s
I20260812 06:17:19.816891 25314 tablet_server.cc:179] TabletServer@127.24.184.129:0 shutting down...
I20260812 06:17:19.821636 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: FlushDeltaMemStoresOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13500,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.822163 25708 maintenance_manager.cc:419] P 5028c21e35dd4f14bea1c89e0a7fa4ea: Scheduling MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8): perf score=1.000000
I20260812 06:17:19.920311 25637 maintenance_manager.cc:643] P 5028c21e35dd4f14bea1c89e0a7fa4ea: MajorDeltaCompactionOp(9fe5e6a6557c4fd7adcbefc7b91532c8) complete. Timing: real 0.098s	user 0.060s	sys 0.038s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":778,"lbm_read_time_us":7120,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17534,"lbm_writes_lt_1ms":343,"mutex_wait_us":298,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":61568,"update_count":1500}
I20260812 06:17:19.921059 25314 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:19.921324 25314 tablet_replica.cc:333] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea: stopping tablet replica
I20260812 06:17:19.921514 25314 raft_consensus.cc:2243] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:19.921730 25314 raft_consensus.cc:2272] T 9fe5e6a6557c4fd7adcbefc7b91532c8 P 5028c21e35dd4f14bea1c89e0a7fa4ea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:19.925963 25314 tablet_server.cc:196] TabletServer@127.24.184.129:0 shutdown complete.
I20260812 06:17:19.952698 25314 master.cc:562] Master@127.24.184.190:46107 shutting down...
I20260812 06:17:19.956409 25314 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:19.956626 25314 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:19.956725 25314 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6352b8d2ede34d4db1ebd61483e59363: stopping tablet replica
I20260812 06:17:19.969425 25314 master.cc:584] Master@127.24.184.190:46107 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5497 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11012 ms total)

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