[==========] 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:18:40.128861  6362 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.54.190:42485
I20260812 06:18:40.129987  6362 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:18:40.130687  6362 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.139344  6371 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:18:40.139460  6375 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:18:40.139674  6362 server_base.cc:1061] running on GCE node
W20260812 06:18:40.139693  6372 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:18:40.140322  6362 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.140470  6362 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:18:40.140529  6362 hybrid_clock.cc:648] HybridClock initialized: now 1786515520140526 us; error 0 us; skew 500 ppm
I20260812 06:18:40.142674  6362 webserver.cc:533] Webserver started at http://127.6.54.190:40439/ using document root <none> and password file <none>
I20260812 06:18:40.143323  6362 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.143427  6362 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.143714  6362 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.145694  6362 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/master-0-root/instance:
uuid: "bca81e5bbb2b4916a36c05b56484e11d"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-kvfs"
I20260812 06:18:40.150249  6362 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.000s	sys 0.005s
I20260812 06:18:40.152940  6383 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:18:40.154175  6362 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:18:40.154301  6362 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/master-0-root
uuid: "bca81e5bbb2b4916a36c05b56484e11d"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-kvfs"
I20260812 06:18:40.154398  6362 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-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:18:40.170380  6362 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.171121  6362 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:18:40.171286  6362 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.180868  6362 rpc_server.cc:307] RPC server started. Bound to: 127.6.54.190:42485
I20260812 06:18:40.180882  6460 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.54.190:42485 every 8 connection(s)
I20260812 06:18:40.183390  6462 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:18:40.189291  6462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: Bootstrap starting.
I20260812 06:18:40.191866  6462 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.193140  6462 log.cc:826] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:40.195133  6462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: No bootstrap required, opened a new log
I20260812 06:18:40.199075  6462 raft_consensus.cc:359] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER }
I20260812 06:18:40.199301  6462 raft_consensus.cc:385] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.199386  6462 raft_consensus.cc:740] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bca81e5bbb2b4916a36c05b56484e11d, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.200852  6462 consensus_queue.cc:260] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [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: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER }
I20260812 06:18:40.201103  6462 raft_consensus.cc:399] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.201202  6462 raft_consensus.cc:493] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.201387  6462 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.202489  6462 raft_consensus.cc:515] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER }
I20260812 06:18:40.203109  6462 leader_election.cc:304] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [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: bca81e5bbb2b4916a36c05b56484e11d; no voters: 
I20260812 06:18:40.203583  6462 leader_election.cc:290] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.203794  6465 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.204144  6465 raft_consensus.cc:697] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 1 LEADER]: Becoming Leader. State: Replica: bca81e5bbb2b4916a36c05b56484e11d, State: Running, Role: LEADER
I20260812 06:18:40.204603  6465 consensus_queue.cc:237] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [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: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER }
I20260812 06:18:40.204913  6462 sys_catalog.cc:565] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.206674  6468 sys_catalog.cc:455] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [sys.catalog]: SysCatalogTable state changed. Reason: New leader bca81e5bbb2b4916a36c05b56484e11d. Latest consensus state: current_term: 1 leader_uuid: "bca81e5bbb2b4916a36c05b56484e11d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER } }
I20260812 06:18:40.206743  6466 sys_catalog.cc:455] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bca81e5bbb2b4916a36c05b56484e11d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bca81e5bbb2b4916a36c05b56484e11d" member_type: VOTER } }
I20260812 06:18:40.206815  6468 sys_catalog.cc:458] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.206856  6466 sys_catalog.cc:458] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.207191  6482 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.209762  6482 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.210075  6362 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.215058  6482 catalog_manager.cc:1383] Generated new cluster ID: 052995bdcf9b42ca931137c8138c0816
I20260812 06:18:40.215149  6482 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.229055  6482 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.230341  6482 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.244609  6482 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: Generated new TSK 0
I20260812 06:18:40.245548  6482 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.275911  6362 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.279498  6495 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:18:40.279454  6498 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:18:40.279609  6494 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:18:40.280408  6362 server_base.cc:1061] running on GCE node
I20260812 06:18:40.280668  6362 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.280712  6362 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:18:40.280730  6362 hybrid_clock.cc:648] HybridClock initialized: now 1786515520280730 us; error 0 us; skew 500 ppm
I20260812 06:18:40.281903  6362 webserver.cc:533] Webserver started at http://127.6.54.129:45865/ using document root <none> and password file <none>
I20260812 06:18:40.282135  6362 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.282192  6362 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.282301  6362 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.282753  6362 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/instance:
uuid: "85a1d97b554d4401b9600462702206e7"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-kvfs"
I20260812 06:18:40.284531  6362 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:40.285662  6506 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:18:40.285928  6362 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.286006  6362 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root
uuid: "85a1d97b554d4401b9600462702206e7"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-kvfs"
I20260812 06:18:40.286113  6362 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-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:18:40.292587  6362 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.293141  6362 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.293659  6362 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.294661  6362 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.294746  6362 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.294831  6362 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.294883  6362 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.302357  6362 rpc_server.cc:307] RPC server started. Bound to: 127.6.54.129:45321
I20260812 06:18:40.302372  6608 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.54.129:45321 every 8 connection(s)
I20260812 06:18:40.317577  6609 heartbeater.cc:344] Connected to a master server at 127.6.54.190:42485
I20260812 06:18:40.317878  6609 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.318372  6609 heartbeater.cc:507] Master 127.6.54.190:42485 requested a full tablet report, sending...
I20260812 06:18:40.319936  6402 ts_manager.cc:194] Registered new tserver with Master: 85a1d97b554d4401b9600462702206e7 (127.6.54.129:45321)
I20260812 06:18:40.320055  6362 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016983308s
I20260812 06:18:40.321384  6402 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50746
I20260812 06:18:40.331878  6402 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50752:
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:18:40.353961  6552 tablet_service.cc:1511] Processing CreateTablet for tablet 9aa272cfe5d84ac29f691cfd7e37815e (DEFAULT_TABLE table=heavy-update-compaction-test [id=f6e2c3a62145400095b1c9b7d5b3493e]), partition=
I20260812 06:18:40.354699  6552 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9aa272cfe5d84ac29f691cfd7e37815e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.358389  6627 tablet_bootstrap.cc:492] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Bootstrap starting.
I20260812 06:18:40.360352  6627 tablet_bootstrap.cc:654] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.362082  6627 tablet_bootstrap.cc:492] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: No bootstrap required, opened a new log
I20260812 06:18:40.362195  6627 ts_tablet_manager.cc:1403] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:18:40.362986  6627 raft_consensus.cc:359] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85a1d97b554d4401b9600462702206e7" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 45321 } }
I20260812 06:18:40.363125  6627 raft_consensus.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.363152  6627 raft_consensus.cc:740] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 85a1d97b554d4401b9600462702206e7, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.363363  6627 consensus_queue.cc:260] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [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: "85a1d97b554d4401b9600462702206e7" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 45321 } }
I20260812 06:18:40.363480  6627 raft_consensus.cc:399] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.363560  6627 raft_consensus.cc:493] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.363617  6627 raft_consensus.cc:3060] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.364598  6627 raft_consensus.cc:515] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85a1d97b554d4401b9600462702206e7" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 45321 } }
I20260812 06:18:40.364729  6627 leader_election.cc:304] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [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: 85a1d97b554d4401b9600462702206e7; no voters: 
I20260812 06:18:40.365056  6627 leader_election.cc:290] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.365389  6629 raft_consensus.cc:2804] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.365546  6627 ts_tablet_manager.cc:1434] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:40.365670  6629 raft_consensus.cc:697] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 1 LEADER]: Becoming Leader. State: Replica: 85a1d97b554d4401b9600462702206e7, State: Running, Role: LEADER
I20260812 06:18:40.365852  6629 consensus_queue.cc:237] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [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: "85a1d97b554d4401b9600462702206e7" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 45321 } }
I20260812 06:18:40.366093  6609 heartbeater.cc:499] Master 127.6.54.190:42485 was elected leader, sending a full tablet report...
I20260812 06:18:40.368974  6402 catalog_manager.cc:5719] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 85a1d97b554d4401b9600462702206e7 (127.6.54.129). New cstate: current_term: 1 leader_uuid: "85a1d97b554d4401b9600462702206e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "85a1d97b554d4401b9600462702206e7" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 45321 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.443953  6362 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.069s	user 0.018s	sys 0.017s
I20260812 06:18:40.553584  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=15.086190
I20260812 06:18:40.711164  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.157s	user 0.111s	sys 0.035s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":239,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":835,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36241,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":134,"threads_started":1,"update_count":1000}
I20260812 06:18:40.712513  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e): free 8725963 bytes of WAL
I20260812 06:18:40.712857  6518 log_reader.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e: removed 1 log segments from log reader
I20260812 06:18:40.712929  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000001 (ops 1-6)
I20260812 06:18:40.715499  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:40.715957  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e): 12308959 bytes on disk
I20260812 06:18:40.716710  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.717350  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:40.734751  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.735405  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:40.865841  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.130s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":8128,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22002,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":347,"threads_started":5,"update_count":1500}
I20260812 06:18:40.866626  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:40.919934  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.053s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19070,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.920629  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:40.932744  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.933266  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:41.072583  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.139s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":10033,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26422,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:41.073330  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:41.134692  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.061s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.135319  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:41.148377  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.148895  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:41.312934  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.164s	user 0.103s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":444,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27417,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.313687  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:41.371743  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.058s	user 0.020s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":24788,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.372341  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:41.385326  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.386045  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:41.535586  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.149s	user 0.141s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":10864,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29239,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:41.536331  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:41.585047  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19928,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.585672  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:41.599556  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.600147  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:41.746974  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.147s	user 0.110s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":401,"lbm_read_time_us":10735,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29876,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:18:41.747761  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:41.798207  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.050s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15901,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.799144  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:41.940376  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.141s	user 0.096s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528783,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":966,"lbm_read_time_us":9639,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22233,"lbm_writes_lt_1ms":343,"mutex_wait_us":407,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:41.940992  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:41.999410  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.058s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19982,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.000322  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:42.013466  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.014168  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:42.151520  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.137s	user 0.118s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":9827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25697,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2000}
I20260812 06:18:42.152163  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=10.126437
I20260812 06:18:42.200706  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.048s	user 0.012s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16636,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.201297  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:42.214813  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.215513  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:42.249852  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.034s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":129,"dirs.run_cpu_time_us":411,"dirs.run_wall_time_us":2067,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1779,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:42.250732  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e): free 132571250 bytes of WAL
I20260812 06:18:42.250988  6518 log_reader.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e: removed 13 log segments from log reader
I20260812 06:18:42.251034  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000002 (ops 7-11)
I20260812 06:18:42.251065  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000003 (ops 12-16)
I20260812 06:18:42.251129  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000004 (ops 17-21)
I20260812 06:18:42.251159  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000005 (ops 22-26)
I20260812 06:18:42.251199  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000006 (ops 27-31)
I20260812 06:18:42.251262  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000007 (ops 32-36)
I20260812 06:18:42.251302  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000008 (ops 37-40)
I20260812 06:18:42.251339  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000009 (ops 41-45)
I20260812 06:18:42.251379  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000010 (ops 46-50)
I20260812 06:18:42.251416  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000011 (ops 51-55)
I20260812 06:18:42.251457  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000012 (ops 56-60)
I20260812 06:18:42.251494  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000013 (ops 61-64)
I20260812 06:18:42.251534  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000014 (ops 65-69)
I20260812 06:18:42.282186  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:42.282702  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=6.157687
I20260812 06:18:42.308769  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10820,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:42.309441  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:42.507512  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.198s	user 0.131s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":348,"lbm_read_time_us":11089,"lbm_reads_lt_1ms":665,"lbm_write_time_us":39105,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30976,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:18:42.508191  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:42.566073  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.056s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24677,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.566628  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e): 473 bytes on disk
I20260812 06:18:42.567107  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e) 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:18:42.567601  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:42.582631  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5649,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.583287  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:42.762497  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.179s	user 0.136s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":12017,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33300,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:42.764381  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:42.819780  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.055s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23855,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.820598  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:42.832211  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.832921  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:43.024797  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.192s	user 0.127s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":13067,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29862,"lbm_writes_lt_1ms":543,"mutex_wait_us":115,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:18:43.025444  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:43.084277  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.059s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25810,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.085171  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:43.248447  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.163s	user 0.119s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":11480,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27312,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:43.250411  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=11.118625
I20260812 06:18:43.292621  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.042s	user 0.038s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18040,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.293399  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:43.319654  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5020,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.320279  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:43.331073  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.331593  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:43.528815  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.197s	user 0.125s	sys 0.066s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":253,"lbm_read_time_us":13046,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31784,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:18:43.529388  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=11.118625
I20260812 06:18:43.572288  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.043s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18416,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.574855  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:43.603896  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.027s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4821,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.604676  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:43.615984  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.616600  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:43.826838  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.210s	user 0.157s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":225,"lbm_read_time_us":14046,"lbm_reads_lt_1ms":573,"lbm_write_time_us":38833,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":2500}
I20260812 06:18:43.827773  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:43.888612  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.061s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.889199  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:43.900745  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.901373  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:43.937455  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":383,"dirs.run_wall_time_us":2116,"drs_written":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2078,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:43.938354  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e): free 120553431 bytes of WAL
I20260812 06:18:43.938656  6518 log_reader.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e: removed 12 log segments from log reader
I20260812 06:18:43.938736  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000015 (ops 70-74)
I20260812 06:18:43.938791  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000016 (ops 75-79)
I20260812 06:18:43.938853  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000017 (ops 80-84)
I20260812 06:18:43.938898  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000018 (ops 85-89)
I20260812 06:18:43.938936  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000019 (ops 90-94)
I20260812 06:18:43.938977  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000020 (ops 95-98)
I20260812 06:18:43.939062  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000021 (ops 99-103)
I20260812 06:18:43.939107  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000022 (ops 104-108)
I20260812 06:18:43.939148  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000023 (ops 109-113)
I20260812 06:18:43.939188  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000024 (ops 114-118)
I20260812 06:18:43.939226  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000025 (ops 119-122)
I20260812 06:18:43.939266  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000026 (ops 123-127)
I20260812 06:18:43.973170  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:18:43.973815  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=3.181125
I20260812 06:18:44.006219  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.032s	user 0.021s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8056,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:44.007176  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:44.025734  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6338,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.026607  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:44.298204  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.271s	user 0.188s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938775,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":538,"lbm_read_time_us":20354,"lbm_reads_lt_1ms":774,"lbm_write_time_us":50609,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":51712,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:18:44.299660  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e): 482 bytes on disk
I20260812 06:18:44.300578  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":146,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.310912  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=15.087375
I20260812 06:18:44.373739  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.063s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":25642,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:44.374786  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:44.390347  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4307785,"delete_count":0,"lbm_write_time_us":6118,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:44.390887  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:44.400790  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":3474,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:18:44.401463  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:44.635959  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.234s	user 0.162s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836242,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1297,"lbm_read_time_us":16833,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39791,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:44.636685  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:44.690449  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.053s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21964,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.691128  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:44.882061  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.191s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":188,"lbm_read_time_us":11658,"lbm_reads_lt_1ms":463,"lbm_write_time_us":33317,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":87808,"update_count":2000}
I20260812 06:18:44.884758  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:44.962381  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.077s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":46771,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.963129  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:44.994870  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.032s	user 0.007s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.996229  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:45.008383  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.012s	user 0.006s	sys 0.001s Metrics: {"bytes_written":1312955,"delete_count":0,"lbm_write_time_us":1745,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:18:45.008904  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.196750
I20260812 06:18:45.019194  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:18:45.019812  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:45.254513  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.234s	user 0.179s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":360,"lbm_read_time_us":16435,"lbm_reads_lt_1ms":674,"lbm_write_time_us":42347,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:45.259860  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:45.334973  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.075s	user 0.039s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24783,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.335745  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:45.357095  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.021s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.357949  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:45.592465  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.234s	user 0.168s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1168,"lbm_read_time_us":15791,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40064,"lbm_writes_lt_1ms":543,"mutex_wait_us":464,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":46976,"update_count":2500}
I20260812 06:18:45.593647  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=11.118625
I20260812 06:18:45.634768  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.041s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17996,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.635504  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:45.654583  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5663,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":450}
I20260812 06:18:45.655143  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:45.712567  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushMRSOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.057s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1637,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2004,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:45.713290  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e): free 112239512 bytes of WAL
I20260812 06:18:45.713533  6518 log_reader.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e: removed 11 log segments from log reader
I20260812 06:18:45.713613  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000027 (ops 128-132)
I20260812 06:18:45.713668  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000028 (ops 133-137)
I20260812 06:18:45.713733  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000029 (ops 138-142)
I20260812 06:18:45.713783  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000030 (ops 143-146)
I20260812 06:18:45.713825  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000031 (ops 147-151)
I20260812 06:18:45.713871  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000032 (ops 152-156)
I20260812 06:18:45.713914  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000033 (ops 157-161)
I20260812 06:18:45.713958  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000034 (ops 162-166)
I20260812 06:18:45.714002  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000035 (ops 167-171)
I20260812 06:18:45.714044  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000036 (ops 172-176)
I20260812 06:18:45.714090  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000037 (ops 177-181)
I20260812 06:18:45.746088  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:45.746726  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=6.157687
I20260812 06:18:45.771127  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.024s	user 0.018s	sys 0.003s Metrics: {"bytes_written":8164054,"delete_count":0,"lbm_write_time_us":10468,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":995}
I20260812 06:18:45.771658  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e): free 8767197 bytes of WAL
I20260812 06:18:45.771886  6518 log_reader.cc:385] T 9aa272cfe5d84ac29f691cfd7e37815e: removed 1 log segments from log reader
I20260812 06:18:45.771934  6518 log.cc:1079] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/9aa272cfe5d84ac29f691cfd7e37815e/wal-000000038 (ops 182-186)
I20260812 06:18:45.774629  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: LogGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:45.775170  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e): 447 bytes on disk
I20260812 06:18:45.775928  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: UndoDeltaBlockGCOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":129,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.776726  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:45.981480  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.205s	user 0.160s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795225,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":484,"lbm_read_time_us":15635,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36148,"lbm_writes_lt_1ms":642,"mutex_wait_us":34,"peak_mem_usage":75501437,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":107,"threads_started":1,"update_count":2995}
I20260812 06:18:45.982201  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=14.095187
I20260812 06:18:46.036198  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.054s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16450932,"delete_count":0,"lbm_write_time_us":24343,"lbm_writes_lt_1ms":404,"reinsert_count":0,"update_count":2005}
I20260812 06:18:46.036780  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=2.188937
I20260812 06:18:46.053215  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: FlushDeltaMemStoresOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.053834  6610 maintenance_manager.cc:419] P 85a1d97b554d4401b9600462702206e7: Scheduling MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e): perf score=1.000000
I20260812 06:18:46.140820  6362 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.697s	user 2.087s	sys 0.171s
I20260812 06:18:46.214133  6362 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.003s	sys 0.000s
I20260812 06:18:46.214865  6362 tablet_server.cc:179] TabletServer@127.6.54.129:0 shutting down...
I20260812 06:18:46.222693  6518 maintenance_manager.cc:643] P 85a1d97b554d4401b9600462702206e7: MajorDeltaCompactionOp(9aa272cfe5d84ac29f691cfd7e37815e) complete. Timing: real 0.169s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774754,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":12904,"lbm_reads_lt_1ms":565,"lbm_write_time_us":30823,"lbm_writes_lt_1ms":544,"mutex_wait_us":40,"peak_mem_usage":63156935,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2505}
I20260812 06:18:46.223346  6362 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.224377  6362 tablet_replica.cc:333] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7: stopping tablet replica
I20260812 06:18:46.224655  6362 raft_consensus.cc:2243] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.224931  6362 raft_consensus.cc:2272] T 9aa272cfe5d84ac29f691cfd7e37815e P 85a1d97b554d4401b9600462702206e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.243541  6362 tablet_server.cc:196] TabletServer@127.6.54.129:0 shutdown complete.
I20260812 06:18:46.271692  6362 master.cc:562] Master@127.6.54.190:42485 shutting down...
I20260812 06:18:46.278192  6362 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.278419  6362 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.278476  6362 tablet_replica.cc:333] T 00000000000000000000000000000000 P bca81e5bbb2b4916a36c05b56484e11d: stopping tablet replica
I20260812 06:18:46.292272  6362 master.cc:584] Master@127.6.54.190:42485 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6259 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:46.400321  6362 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.54.190:37517
I20260812 06:18:46.400718  6362 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.402959  6656 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:18:46.403015  6362 server_base.cc:1061] running on GCE node
W20260812 06:18:46.403064  6655 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:18:46.403210  6658 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:18:46.403647  6362 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.403844  6362 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:18:46.403939  6362 hybrid_clock.cc:648] HybridClock initialized: now 1786515526403937 us; error 0 us; skew 500 ppm
I20260812 06:18:46.405124  6362 webserver.cc:533] Webserver started at http://127.6.54.190:42945/ using document root <none> and password file <none>
I20260812 06:18:46.405332  6362 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.405400  6362 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.405490  6362 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.405951  6362 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/master-0-root/instance:
uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-kvfs"
I20260812 06:18:46.407708  6362 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:46.408993  6667 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:18:46.409343  6362 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:46.409426  6362 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/master-0-root
uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-kvfs"
I20260812 06:18:46.409546  6362 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-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:18:46.418454  6362 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.418951  6362 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.423986  6362 rpc_server.cc:307] RPC server started. Bound to: 127.6.54.190:37517
I20260812 06:18:46.426057  6749 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.54.190:37517 every 8 connection(s)
I20260812 06:18:46.429335  6750 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:18:46.431443  6750 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85: Bootstrap starting.
I20260812 06:18:46.432403  6750 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.433490  6750 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85: No bootstrap required, opened a new log
I20260812 06:18:46.433954  6750 raft_consensus.cc:359] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER }
I20260812 06:18:46.434052  6750 raft_consensus.cc:385] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.434077  6750 raft_consensus.cc:740] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d4f516a6a3734ed0b9965cc7bfe1dc85, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.434269  6750 consensus_queue.cc:260] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [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: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER }
I20260812 06:18:46.434366  6750 raft_consensus.cc:399] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.434392  6750 raft_consensus.cc:493] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.434460  6750 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.435247  6750 raft_consensus.cc:515] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER }
I20260812 06:18:46.435374  6750 leader_election.cc:304] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [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: d4f516a6a3734ed0b9965cc7bfe1dc85; no voters: 
I20260812 06:18:46.435653  6750 leader_election.cc:290] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.435887  6753 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.436211  6753 raft_consensus.cc:697] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 1 LEADER]: Becoming Leader. State: Replica: d4f516a6a3734ed0b9965cc7bfe1dc85, State: Running, Role: LEADER
I20260812 06:18:46.436379  6753 consensus_queue.cc:237] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [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: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER }
I20260812 06:18:46.436496  6750 sys_catalog.cc:565] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:46.436944  6754 sys_catalog.cc:455] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER } }
I20260812 06:18:46.436968  6755 sys_catalog.cc:455] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d4f516a6a3734ed0b9965cc7bfe1dc85. Latest consensus state: current_term: 1 leader_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d4f516a6a3734ed0b9965cc7bfe1dc85" member_type: VOTER } }
I20260812 06:18:46.437063  6754 sys_catalog.cc:458] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.437080  6755 sys_catalog.cc:458] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:46.437361  6758 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:46.438226  6758 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:46.438712  6362 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:46.440474  6758 catalog_manager.cc:1383] Generated new cluster ID: a9a2c00da1cc401e9ffbb7c6e6e7b285
I20260812 06:18:46.440559  6758 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:46.447964  6758 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:46.448585  6758 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:46.458772  6758 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85: Generated new TSK 0
I20260812 06:18:46.459000  6758 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:46.471429  6362 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:46.474023  6782 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:18:46.474185  6362 server_base.cc:1061] running on GCE node
W20260812 06:18:46.474035  6779 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:18:46.474052  6778 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:18:46.474676  6362 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:46.474735  6362 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:18:46.474756  6362 hybrid_clock.cc:648] HybridClock initialized: now 1786515526474755 us; error 0 us; skew 500 ppm
I20260812 06:18:46.475903  6362 webserver.cc:533] Webserver started at http://127.6.54.129:45885/ using document root <none> and password file <none>
I20260812 06:18:46.476146  6362 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:46.476207  6362 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:46.476295  6362 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:46.476758  6362 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/instance:
uuid: "fb1faa892fd04ccea7bc0b71981ff220"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-kvfs"
I20260812 06:18:46.479104  6362 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:46.480768  6787 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:18:46.481133  6362 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:46.481215  6362 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root
uuid: "fb1faa892fd04ccea7bc0b71981ff220"
format_stamp: "Formatted at 2026-08-12 06:18:46 on dist-test-slave-kvfs"
I20260812 06:18:46.481293  6362 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-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:18:46.503412  6362 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:46.503866  6362 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:46.504258  6362 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:46.504829  6362 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:46.504874  6362 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.504912  6362 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:46.504958  6362 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:46.510109  6362 rpc_server.cc:307] RPC server started. Bound to: 127.6.54.129:32963
I20260812 06:18:46.510418  6866 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.54.129:32963 every 8 connection(s)
I20260812 06:18:46.516058  6867 heartbeater.cc:344] Connected to a master server at 127.6.54.190:37517
I20260812 06:18:46.516183  6867 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:46.516420  6867 heartbeater.cc:507] Master 127.6.54.190:37517 requested a full tablet report, sending...
I20260812 06:18:46.517133  6692 ts_manager.cc:194] Registered new tserver with Master: fb1faa892fd04ccea7bc0b71981ff220 (127.6.54.129:32963)
I20260812 06:18:46.517539  6362 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006843028s
I20260812 06:18:46.518303  6692 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43794
I20260812 06:18:46.525732  6692 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43800:
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:18:46.535851  6821 tablet_service.cc:1511] Processing CreateTablet for tablet 66b4b5ec63174d9e871169780c556274 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f5063d1df6094d41b87ca2206910a324]), partition=
I20260812 06:18:46.536216  6821 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 66b4b5ec63174d9e871169780c556274. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:46.538344  6885 tablet_bootstrap.cc:492] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Bootstrap starting.
I20260812 06:18:46.539266  6885 tablet_bootstrap.cc:654] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:46.540908  6885 tablet_bootstrap.cc:492] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: No bootstrap required, opened a new log
I20260812 06:18:46.541069  6885 ts_tablet_manager.cc:1403] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:46.541751  6885 raft_consensus.cc:359] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1faa892fd04ccea7bc0b71981ff220" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 32963 } }
I20260812 06:18:46.541914  6885 raft_consensus.cc:385] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:46.541956  6885 raft_consensus.cc:740] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fb1faa892fd04ccea7bc0b71981ff220, State: Initialized, Role: FOLLOWER
I20260812 06:18:46.542160  6885 consensus_queue.cc:260] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [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: "fb1faa892fd04ccea7bc0b71981ff220" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 32963 } }
I20260812 06:18:46.542272  6885 raft_consensus.cc:399] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:46.542322  6885 raft_consensus.cc:493] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:46.542377  6885 raft_consensus.cc:3060] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:46.543341  6885 raft_consensus.cc:515] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1faa892fd04ccea7bc0b71981ff220" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 32963 } }
I20260812 06:18:46.543545  6885 leader_election.cc:304] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [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: fb1faa892fd04ccea7bc0b71981ff220; no voters: 
I20260812 06:18:46.543823  6885 leader_election.cc:290] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:46.543998  6890 raft_consensus.cc:2804] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:46.544274  6885 ts_tablet_manager.cc:1434] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:46.544306  6890 raft_consensus.cc:697] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 1 LEADER]: Becoming Leader. State: Replica: fb1faa892fd04ccea7bc0b71981ff220, State: Running, Role: LEADER
I20260812 06:18:46.544344  6867 heartbeater.cc:499] Master 127.6.54.190:37517 was elected leader, sending a full tablet report...
I20260812 06:18:46.544454  6890 consensus_queue.cc:237] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [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: "fb1faa892fd04ccea7bc0b71981ff220" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 32963 } }
I20260812 06:18:46.546380  6690 catalog_manager.cc:5719] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 reported cstate change: term changed from 0 to 1, leader changed from <none> to fb1faa892fd04ccea7bc0b71981ff220 (127.6.54.129). New cstate: current_term: 1 leader_uuid: "fb1faa892fd04ccea7bc0b71981ff220" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1faa892fd04ccea7bc0b71981ff220" member_type: VOTER last_known_addr { host: "127.6.54.129" port: 32963 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:46.611312  6362 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.009s	sys 0.015s
I20260812 06:18:46.761300  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushMRSOp(66b4b5ec63174d9e871169780c556274): perf score=15.086190
I20260812 06:18:46.957861  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushMRSOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.196s	user 0.143s	sys 0.037s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":976,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44286,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:18:46.958796  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling LogGCOp(66b4b5ec63174d9e871169780c556274): free 20290830 bytes of WAL
I20260812 06:18:46.959067  6792 log_reader.cc:385] T 66b4b5ec63174d9e871169780c556274: removed 2 log segments from log reader
I20260812 06:18:46.959116  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000001 (ops 1-6)
I20260812 06:18:46.959149  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000002 (ops 7-10)
I20260812 06:18:46.964726  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: LogGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:46.965227  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274): 16411376 bytes on disk
I20260812 06:18:46.966109  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":186,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.966976  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:46.982183  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.984436  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:47.166304  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.181s	user 0.108s	sys 0.073s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":12450,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27967,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"thread_start_us":426,"threads_started":5,"update_count":2000}
I20260812 06:18:47.167384  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:47.213927  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":20773,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.214478  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:47.226939  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.227490  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:47.375402  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.148s	user 0.124s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":10876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26844,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29312,"update_count":2000}
I20260812 06:18:47.376250  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:47.435237  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.059s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307519,"delete_count":0,"lbm_write_time_us":19206,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.435832  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:47.452092  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.452847  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:47.593228  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.140s	user 0.096s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631341,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":10423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27970,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:47.593957  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:47.639307  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20209,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.640095  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:47.761976  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.122s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":206,"lbm_read_time_us":6621,"lbm_reads_lt_1ms":367,"lbm_write_time_us":23012,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":1500}
I20260812 06:18:47.762634  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:47.812981  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.050s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20295,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.813831  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:47.939724  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.126s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1122,"lbm_read_time_us":7271,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22756,"lbm_writes_lt_1ms":343,"mutex_wait_us":379,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":65152,"update_count":1500}
I20260812 06:18:47.940313  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:47.990309  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.050s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19098,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.990841  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:48.002910  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.003822  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:48.156081  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.152s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":283,"lbm_read_time_us":11660,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26570,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:48.156814  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:48.218230  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.061s	user 0.021s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18197,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.219297  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:48.236313  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.241777  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:48.408941  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.167s	user 0.116s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":13243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23892,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:48.409720  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:48.466399  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.056s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19349,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.467099  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:48.480298  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.481185  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushMRSOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:48.516252  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushMRSOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.035s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":378,"dirs.run_wall_time_us":1696,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1835,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:48.516891  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling LogGCOp(66b4b5ec63174d9e871169780c556274): free 120553374 bytes of WAL
I20260812 06:18:48.517139  6792 log_reader.cc:385] T 66b4b5ec63174d9e871169780c556274: removed 12 log segments from log reader
I20260812 06:18:48.517198  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000003 (ops 11-15)
I20260812 06:18:48.517263  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000004 (ops 16-20)
I20260812 06:18:48.517309  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000005 (ops 21-24)
I20260812 06:18:48.517354  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000006 (ops 25-29)
I20260812 06:18:48.517398  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000007 (ops 30-34)
I20260812 06:18:48.517438  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000008 (ops 35-39)
I20260812 06:18:48.517462  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000009 (ops 40-44)
I20260812 06:18:48.517518  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000010 (ops 45-49)
I20260812 06:18:48.517560  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000011 (ops 50-54)
I20260812 06:18:48.517594  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000012 (ops 55-58)
I20260812 06:18:48.517633  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000013 (ops 59-63)
I20260812 06:18:48.517671  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000014 (ops 64-68)
I20260812 06:18:48.549926  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: LogGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:48.550413  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274): 483 bytes on disk
I20260812 06:18:48.550886  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.551373  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=3.181125
I20260812 06:18:48.565016  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5293,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.565552  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:48.587735  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3761,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.588871  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:48.821733  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.233s	user 0.149s	sys 0.083s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":211,"lbm_read_time_us":16203,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38942,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28928,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:48.822567  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:48.877663  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.054s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23405,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.878223  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:48.898800  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.899433  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:49.094377  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.195s	user 0.134s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":708,"lbm_read_time_us":14893,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29149,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:18:49.095222  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:49.151847  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.056s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.152590  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:49.174990  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.022s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.175638  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:49.385366  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.210s	user 0.141s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":912,"lbm_read_time_us":11882,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34087,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:49.385972  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:49.436775  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.051s	user 0.016s	sys 0.032s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22048,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.437342  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:49.453475  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.454627  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:49.622424  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.167s	user 0.131s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":946,"lbm_read_time_us":11837,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33831,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":257920,"update_count":2500}
I20260812 06:18:49.623296  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=10.126437
I20260812 06:18:49.668780  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.045s	user 0.017s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21201,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:49.669404  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:49.686411  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.687100  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:49.856750  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.169s	user 0.119s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":10532,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30117,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":43264,"update_count":2000}
I20260812 06:18:49.857558  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:49.919598  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.062s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24976,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.920603  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:49.935304  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.935858  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:50.128800  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.193s	user 0.126s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":11874,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35952,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":126848,"update_count":2500}
I20260812 06:18:50.129757  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:50.187443  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.057s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24434,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.188299  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushMRSOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:50.247650  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushMRSOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.059s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":125,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1707,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2665,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:50.248450  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling LogGCOp(66b4b5ec63174d9e871169780c556274): free 129320510 bytes of WAL
I20260812 06:18:50.248723  6792 log_reader.cc:385] T 66b4b5ec63174d9e871169780c556274: removed 13 log segments from log reader
I20260812 06:18:50.248785  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000015 (ops 69-73)
I20260812 06:18:50.248826  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000016 (ops 74-78)
I20260812 06:18:50.248852  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000017 (ops 79-83)
I20260812 06:18:50.248888  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000018 (ops 84-88)
I20260812 06:18:50.248914  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000019 (ops 89-93)
I20260812 06:18:50.248935  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000020 (ops 94-98)
I20260812 06:18:50.248965  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000021 (ops 99-103)
I20260812 06:18:50.248986  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000022 (ops 104-108)
I20260812 06:18:50.249020  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000023 (ops 109-112)
I20260812 06:18:50.249060  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000024 (ops 113-117)
I20260812 06:18:50.249089  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000025 (ops 118-122)
I20260812 06:18:50.249115  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000026 (ops 123-126)
I20260812 06:18:50.249142  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000027 (ops 127-131)
I20260812 06:18:50.282555  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: LogGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.034s	user 0.008s	sys 0.024s Metrics: {}
I20260812 06:18:50.283082  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274): 482 bytes on disk
I20260812 06:18:50.283730  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.284370  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=6.157687
I20260812 06:18:50.318238  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.034s	user 0.023s	sys 0.005s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":12765,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:50.318815  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:50.330853  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.331789  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:50.573148  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.241s	user 0.181s	sys 0.055s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938669,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":234,"lbm_read_time_us":17071,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41898,"lbm_writes_lt_1ms":743,"mutex_wait_us":84,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:50.574749  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=15.087375
I20260812 06:18:50.635736  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.061s	user 0.015s	sys 0.036s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24801,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:50.636272  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:50.649189  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.649782  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:50.663069  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.013s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.663887  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:50.860878  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.197s	user 0.149s	sys 0.047s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":712,"lbm_read_time_us":14088,"lbm_reads_lt_1ms":673,"lbm_write_time_us":42350,"lbm_writes_lt_1ms":643,"mutex_wait_us":147,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":3000}
I20260812 06:18:50.861603  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:50.909466  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.910215  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:50.931566  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.021s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.932189  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:51.105707  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.173s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":10326,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32006,"lbm_writes_lt_1ms":543,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38144,"update_count":2500}
I20260812 06:18:51.106520  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:51.168596  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.062s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28152,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.169477  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:51.192560  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.023s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.193265  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:51.398775  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.205s	user 0.153s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":969,"lbm_read_time_us":13506,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35499,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:51.399784  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:51.458894  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.059s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26267,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.459553  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:51.479112  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.019s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.479887  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:51.660898  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.181s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":12827,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31768,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:51.661751  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=14.095187
I20260812 06:18:51.728196  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.066s	user 0.038s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24477,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:51.728966  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:51.740661  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.011s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4413,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.741235  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushMRSOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:51.786494  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushMRSOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.045s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1957,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1980,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:51.787356  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling LogGCOp(66b4b5ec63174d9e871169780c556274): free 112239554 bytes of WAL
I20260812 06:18:51.787659  6792 log_reader.cc:385] T 66b4b5ec63174d9e871169780c556274: removed 11 log segments from log reader
I20260812 06:18:51.787708  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000028 (ops 132-136)
I20260812 06:18:51.787740  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000029 (ops 137-141)
I20260812 06:18:51.787786  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000030 (ops 142-146)
I20260812 06:18:51.787834  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000031 (ops 147-150)
I20260812 06:18:51.787855  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000032 (ops 151-155)
I20260812 06:18:51.787910  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000033 (ops 156-160)
I20260812 06:18:51.787952  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000034 (ops 161-165)
I20260812 06:18:51.788007  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000035 (ops 166-170)
I20260812 06:18:51.788076  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000036 (ops 171-175)
I20260812 06:18:51.788120  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000037 (ops 176-180)
I20260812 06:18:51.788169  6792 log.cc:1079] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: Deleting log segment in path: /tmp/dist-test-taskPeX7UT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520116938-6362-0/minicluster-data/ts-0-root/wals/66b4b5ec63174d9e871169780c556274/wal-000000038 (ops 181-185)
I20260812 06:18:51.815307  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: LogGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:51.815786  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:51.838459  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.022s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.839068  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274): 446 bytes on disk
I20260812 06:18:51.839493  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: UndoDeltaBlockGCOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:51.840008  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=2.188937
I20260812 06:18:51.851399  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.852128  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274): perf score=1.000000
I20260812 06:18:52.094797  6362 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.483s	user 2.084s	sys 0.118s
I20260812 06:18:52.098196  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: MajorDeltaCompactionOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.246s	user 0.149s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1606,"lbm_read_time_us":16026,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41158,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":124,"threads_started":1,"update_count":3500}
I20260812 06:18:52.099495  6868 maintenance_manager.cc:419] P fb1faa892fd04ccea7bc0b71981ff220: Scheduling FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274): perf score=18.063937
I20260812 06:18:52.129513  6362 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.034s	user 0.002s	sys 0.000s
I20260812 06:18:52.130053  6362 tablet_server.cc:179] TabletServer@127.6.54.129:0 shutting down...
I20260812 06:18:52.164669  6792 maintenance_manager.cc:643] P fb1faa892fd04ccea7bc0b71981ff220: FlushDeltaMemStoresOp(66b4b5ec63174d9e871169780c556274) complete. Timing: real 0.065s	user 0.043s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29845,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.165709  6362 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.166110  6362 tablet_replica.cc:333] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220: stopping tablet replica
I20260812 06:18:52.166344  6362 raft_consensus.cc:2243] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.166604  6362 raft_consensus.cc:2272] T 66b4b5ec63174d9e871169780c556274 P fb1faa892fd04ccea7bc0b71981ff220 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.170921  6362 tablet_server.cc:196] TabletServer@127.6.54.129:0 shutdown complete.
I20260812 06:18:52.175154  6362 master.cc:562] Master@127.6.54.190:37517 shutting down...
I20260812 06:18:52.180949  6362 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.181185  6362 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.181260  6362 tablet_replica.cc:333] T 00000000000000000000000000000000 P d4f516a6a3734ed0b9965cc7bfe1dc85: stopping tablet replica
I20260812 06:18:52.194628  6362 master.cc:584] Master@127.6.54.190:37517 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5907 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12167 ms total)

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