[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:28.827478  9086 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.223.190:39879
I20260812 06:16:28.828521  9086 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:28.829145  9086 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:28.835788  9086 server_base.cc:1061] running on GCE node
W20260812 06:16:28.835899  9093 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.836053  9098 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.836176  9092 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.836726  9086 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.836851  9086 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.836899  9086 hybrid_clock.cc:648] HybridClock initialized: now 1786515388836897 us; error 0 us; skew 500 ppm
I20260812 06:16:28.838611  9086 webserver.cc:533] Webserver started at http://127.8.223.190:33615/ using document root <none> and password file <none>
I20260812 06:16:28.839149  9086 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.839234  9086 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.839555  9086 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.841281  9086 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/master-0-root/instance:
uuid: "d452a2ddd703466590035dfdc8e39f95"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-x4qh"
I20260812 06:16:28.844715  9086 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:28.846844  9108 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.847875  9086 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:28.847998  9086 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/master-0-root
uuid: "d452a2ddd703466590035dfdc8e39f95"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-x4qh"
I20260812 06:16:28.848105  9086 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.860889  9086 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.861555  9086 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:28.861749  9086 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.869387  9194 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.223.190:39879 every 8 connection(s)
I20260812 06:16:28.869398  9086 rpc_server.cc:307] RPC server started. Bound to: 127.8.223.190:39879
I20260812 06:16:28.871807  9195 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:28.877345  9195 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: Bootstrap starting.
I20260812 06:16:28.879827  9195 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:28.880782  9195 log.cc:826] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:28.882550  9195 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: No bootstrap required, opened a new log
I20260812 06:16:28.885474  9195 raft_consensus.cc:359] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER }
I20260812 06:16:28.885643  9195 raft_consensus.cc:385] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:28.885779  9195 raft_consensus.cc:740] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d452a2ddd703466590035dfdc8e39f95, State: Initialized, Role: FOLLOWER
I20260812 06:16:28.886410  9195 consensus_queue.cc:260] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [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: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER }
I20260812 06:16:28.886579  9195 raft_consensus.cc:399] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:28.886652  9195 raft_consensus.cc:493] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:28.886834  9195 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:28.887701  9195 raft_consensus.cc:515] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER }
I20260812 06:16:28.888164  9195 leader_election.cc:304] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [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: d452a2ddd703466590035dfdc8e39f95; no voters: 
I20260812 06:16:28.888517  9195 leader_election.cc:290] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:28.888648  9200 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:28.888922  9200 raft_consensus.cc:697] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 1 LEADER]: Becoming Leader. State: Replica: d452a2ddd703466590035dfdc8e39f95, State: Running, Role: LEADER
I20260812 06:16:28.889413  9200 consensus_queue.cc:237] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [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: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER }
I20260812 06:16:28.889571  9195 sys_catalog.cc:565] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:28.891501  9201 sys_catalog.cc:455] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d452a2ddd703466590035dfdc8e39f95" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER } }
I20260812 06:16:28.891635  9201 sys_catalog.cc:458] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.891494  9202 sys_catalog.cc:455] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d452a2ddd703466590035dfdc8e39f95. Latest consensus state: current_term: 1 leader_uuid: "d452a2ddd703466590035dfdc8e39f95" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d452a2ddd703466590035dfdc8e39f95" member_type: VOTER } }
I20260812 06:16:28.891703  9202 sys_catalog.cc:458] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:28.892020  9086 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:28.894564  9220 catalog_manager.cc:1594] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:28.894655  9220 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:28.894727  9217 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:28.895546  9217 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:28.899969  9217 catalog_manager.cc:1383] Generated new cluster ID: 4371979c27d74541ad806a96d5da90ca
I20260812 06:16:28.900048  9217 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:28.916643  9217 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:28.917583  9217 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:28.937232  9217 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: Generated new TSK 0
I20260812 06:16:28.937958  9217 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:28.957755  9086 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:28.960986  9234 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.961023  9230 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:28.961022  9227 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:28.961532  9086 server_base.cc:1061] running on GCE node
I20260812 06:16:28.961709  9086 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:28.961757  9086 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:28.961786  9086 hybrid_clock.cc:648] HybridClock initialized: now 1786515388961785 us; error 0 us; skew 500 ppm
I20260812 06:16:28.962774  9086 webserver.cc:533] Webserver started at http://127.8.223.129:41475/ using document root <none> and password file <none>
I20260812 06:16:28.962949  9086 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:28.963006  9086 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:28.963084  9086 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:28.963551  9086 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/instance:
uuid: "13104d1d6476473384994f217fc372a8"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-x4qh"
I20260812 06:16:28.965384  9086 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:28.966471  9240 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.966831  9086 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:28.966923  9086 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root
uuid: "13104d1d6476473384994f217fc372a8"
format_stamp: "Formatted at 2026-08-12 06:16:28 on dist-test-slave-x4qh"
I20260812 06:16:28.967010  9086 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:28.980979  9086 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:28.981487  9086 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:28.982054  9086 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:28.982887  9086 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:28.982964  9086 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.983040  9086 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:28.983090  9086 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:28.990247  9086 rpc_server.cc:307] RPC server started. Bound to: 127.8.223.129:44603
I20260812 06:16:28.990286  9343 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.223.129:44603 every 8 connection(s)
I20260812 06:16:29.007447  9344 heartbeater.cc:344] Connected to a master server at 127.8.223.190:39879
I20260812 06:16:29.007710  9344 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:29.008195  9344 heartbeater.cc:507] Master 127.8.223.190:39879 requested a full tablet report, sending...
I20260812 06:16:29.009582  9135 ts_manager.cc:194] Registered new tserver with Master: 13104d1d6476473384994f217fc372a8 (127.8.223.129:44603)
I20260812 06:16:29.009862  9086 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018907854s
I20260812 06:16:29.011080  9135 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42930
I20260812 06:16:29.019902  9135 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42944:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:29.035202  9289 tablet_service.cc:1511] Processing CreateTablet for tablet 7c918768ff5f4aef9a33625debff18a1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=54b7c9a55ea14dc8808db2740386eee8]), partition=
I20260812 06:16:29.035666  9289 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7c918768ff5f4aef9a33625debff18a1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.038790  9376 tablet_bootstrap.cc:492] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Bootstrap starting.
I20260812 06:16:29.040748  9376 tablet_bootstrap.cc:654] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.042523  9376 tablet_bootstrap.cc:492] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: No bootstrap required, opened a new log
I20260812 06:16:29.042608  9376 ts_tablet_manager.cc:1403] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Time spent bootstrapping tablet: real 0.004s	user 0.000s	sys 0.003s
I20260812 06:16:29.043596  9376 raft_consensus.cc:359] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13104d1d6476473384994f217fc372a8" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 44603 } }
I20260812 06:16:29.043697  9376 raft_consensus.cc:385] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.043720  9376 raft_consensus.cc:740] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 13104d1d6476473384994f217fc372a8, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.043929  9376 consensus_queue.cc:260] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [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: "13104d1d6476473384994f217fc372a8" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 44603 } }
I20260812 06:16:29.044044  9376 raft_consensus.cc:399] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.044106  9376 raft_consensus.cc:493] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.044152  9376 raft_consensus.cc:3060] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.045477  9376 raft_consensus.cc:515] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13104d1d6476473384994f217fc372a8" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 44603 } }
I20260812 06:16:29.045598  9376 leader_election.cc:304] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [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: 13104d1d6476473384994f217fc372a8; no voters: 
I20260812 06:16:29.045878  9376 leader_election.cc:290] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.046154  9382 raft_consensus.cc:2804] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.046417  9376 ts_tablet_manager.cc:1434] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:29.046444  9382 raft_consensus.cc:697] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 1 LEADER]: Becoming Leader. State: Replica: 13104d1d6476473384994f217fc372a8, State: Running, Role: LEADER
I20260812 06:16:29.046602  9344 heartbeater.cc:499] Master 127.8.223.190:39879 was elected leader, sending a full tablet report...
I20260812 06:16:29.046658  9382 consensus_queue.cc:237] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [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: "13104d1d6476473384994f217fc372a8" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 44603 } }
I20260812 06:16:29.049986  9135 catalog_manager.cc:5719] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 13104d1d6476473384994f217fc372a8 (127.8.223.129). New cstate: current_term: 1 leader_uuid: "13104d1d6476473384994f217fc372a8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13104d1d6476473384994f217fc372a8" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 44603 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.183596  9086 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.126s	user 0.025s	sys 0.032s
I20260812 06:16:29.241375  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushMRSOp(7c918768ff5f4aef9a33625debff18a1): perf score=6.156503
I20260812 06:16:29.395298  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushMRSOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.154s	user 0.090s	sys 0.060s Metrics: {"bytes_written":8205079,"cfile_init":1,"compiler_manager_pool.queue_time_us":236,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":857,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49565,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":352,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"thread_start_us":152,"threads_started":1,"update_count":1000}
I20260812 06:16:29.396567  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1): 4103815 bytes on disk
I20260812 06:16:29.397396  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.397921  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:29.425814  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.028s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.426344  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:29.440766  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.441212  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:29.583323  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.142s	user 0.113s	sys 0.027s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20549502,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":877,"lbm_read_time_us":9296,"lbm_reads_lt_1ms":469,"lbm_write_time_us":26912,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":312,"threads_started":5,"update_count":2000}
I20260812 06:16:29.583828  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=10.126437
I20260812 06:16:29.631573  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.048s	user 0.006s	sys 0.035s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19162,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.632053  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:29.643393  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.644008  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:29.766882  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.123s	user 0.098s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":672,"lbm_read_time_us":8820,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24162,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:16:29.767491  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=10.126437
I20260812 06:16:29.815557  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.048s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19383,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.816056  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:29.828711  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.829296  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:29.973569  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.144s	user 0.102s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":10066,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25011,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:29.974263  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=11.118625
I20260812 06:16:30.016259  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.042s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18700,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:30.016734  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.041177  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.024s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.041752  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.051692  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3647,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.052205  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:30.218871  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.166s	user 0.122s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651905,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":823,"lbm_read_time_us":12561,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29865,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:30.219781  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=7.149875
I20260812 06:16:30.254519  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.035s	user 0.009s	sys 0.021s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14019,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1050}
I20260812 06:16:30.255266  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.273341  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7482,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:16:30.274055  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:30.461127  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.187s	user 0.154s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3506,"lbm_read_time_us":11194,"lbm_reads_lt_1ms":372,"lbm_write_time_us":28673,"lbm_writes_lt_1ms":343,"mutex_wait_us":2965,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:16:30.463867  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:30.534011  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.070s	user 0.043s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":31971,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.534669  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.556921  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.022s	user 0.003s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:16:30.557760  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.574443  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.575066  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:30.755542  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.180s	user 0.141s	sys 0.032s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754324,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":354,"lbm_read_time_us":12162,"lbm_reads_lt_1ms":665,"lbm_write_time_us":36544,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:16:30.756292  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:30.812075  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.056s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.812629  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:30.823915  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.824391  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushMRSOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:30.856093  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushMRSOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":296,"dirs.run_wall_time_us":1749,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1710,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:30.857128  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling LogGCOp(7c918768ff5f4aef9a33625debff18a1): free 132983204 bytes of WAL
I20260812 06:16:30.857501  9248 log_reader.cc:385] T 7c918768ff5f4aef9a33625debff18a1: removed 13 log segments from log reader
I20260812 06:16:30.857586  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000001 (ops 1-6)
I20260812 06:16:30.857682  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000002 (ops 7-10)
I20260812 06:16:30.857743  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000003 (ops 11-15)
I20260812 06:16:30.857798  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000004 (ops 16-20)
I20260812 06:16:30.857837  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000005 (ops 21-25)
I20260812 06:16:30.857878  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000006 (ops 26-30)
I20260812 06:16:30.857919  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000007 (ops 31-35)
I20260812 06:16:30.857960  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000008 (ops 36-40)
I20260812 06:16:30.858000  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000009 (ops 41-45)
I20260812 06:16:30.858040  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000010 (ops 46-50)
I20260812 06:16:30.858080  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000011 (ops 51-55)
I20260812 06:16:30.858119  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000012 (ops 56-60)
I20260812 06:16:30.858160  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000013 (ops 61-65)
I20260812 06:16:30.891597  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: LogGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:16:30.892239  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1): 483 bytes on disk
I20260812 06:16:30.892745  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:30.893329  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=5.165500
I20260812 06:16:30.949131  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.056s	user 0.007s	sys 0.008s Metrics: {"bytes_written":6358990,"delete_count":0,"lbm_write_time_us":6841,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:30.949728  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=4.173312
I20260812 06:16:30.965796  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":5948759,"delete_count":0,"lbm_write_time_us":6610,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:16:30.966224  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:31.175619  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.209s	user 0.154s	sys 0.052s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":36959274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":335,"lbm_read_time_us":15818,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44535,"lbm_writes_lt_1ms":843,"mutex_wait_us":60,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":11264,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:16:31.176402  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=18.063937
I20260812 06:16:31.254948  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.078s	user 0.031s	sys 0.043s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":27555,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:31.256048  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:31.275067  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.275723  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:31.486382  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.210s	user 0.144s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754209,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":539,"lbm_read_time_us":16053,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36877,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:31.487125  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=15.087375
I20260812 06:16:31.550132  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.063s	user 0.013s	sys 0.046s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24879,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:31.550662  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:31.571125  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.020s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:31.571593  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:31.582530  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.582985  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:31.783872  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.201s	user 0.153s	sys 0.047s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":599,"lbm_read_time_us":15190,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36234,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":3000}
I20260812 06:16:31.784545  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:31.847102  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.062s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22560,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.847640  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:31.859122  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.859817  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:32.039448  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.179s	user 0.104s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":14088,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28477,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:16:32.043840  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:32.102203  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.058s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:32.102914  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:32.120100  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6531,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.120615  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:32.304333  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.183s	user 0.124s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":624,"lbm_read_time_us":13135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30377,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":72832,"update_count":2500}
I20260812 06:16:32.304951  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:32.362556  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.057s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22441,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.363098  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:32.374047  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.374472  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushMRSOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:32.408334  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushMRSOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2104,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:32.409040  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:32.573438  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.164s	user 0.139s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":10814,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30063,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:32.574100  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling LogGCOp(7c918768ff5f4aef9a33625debff18a1): free 120553390 bytes of WAL
I20260812 06:16:32.574440  9248 log_reader.cc:385] T 7c918768ff5f4aef9a33625debff18a1: removed 12 log segments from log reader
I20260812 06:16:32.574514  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000014 (ops 66-70)
I20260812 06:16:32.574563  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000015 (ops 71-74)
I20260812 06:16:32.574608  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000016 (ops 75-79)
I20260812 06:16:32.574699  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000017 (ops 80-84)
I20260812 06:16:32.574749  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000018 (ops 85-88)
I20260812 06:16:32.574808  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000019 (ops 89-93)
I20260812 06:16:32.574862  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000020 (ops 94-98)
I20260812 06:16:32.574932  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000021 (ops 99-103)
I20260812 06:16:32.574978  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000022 (ops 104-108)
I20260812 06:16:32.575021  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000023 (ops 109-113)
I20260812 06:16:32.575063  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000024 (ops 114-118)
I20260812 06:16:32.575106  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000025 (ops 119-123)
I20260812 06:16:32.610237  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: LogGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.036s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:16:32.610793  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=17.071750
I20260812 06:16:32.670573  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.060s	user 0.038s	sys 0.019s Metrics: {"bytes_written":18707250,"delete_count":0,"lbm_write_time_us":22628,"lbm_writes_lt_1ms":459,"reinsert_count":0,"update_count":2280}
I20260812 06:16:32.671202  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=4.173312
I20260812 06:16:32.686002  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5907732,"delete_count":0,"lbm_write_time_us":6045,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:16:32.686487  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1): 472 bytes on disk
I20260812 06:16:32.686944  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.687584  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:32.900118  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.212s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":847,"lbm_read_time_us":15761,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34246,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":3000}
I20260812 06:16:32.900771  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:32.960028  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.059s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20657,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.960619  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:32.971692  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.972131  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:33.149008  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.177s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":390,"lbm_read_time_us":12636,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30308,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:16:33.149682  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:33.213002  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.063s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23124,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.213604  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.224733  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.225368  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:33.397091  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.171s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":741,"lbm_read_time_us":12765,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31493,"lbm_writes_lt_1ms":543,"mutex_wait_us":382,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:16:33.397809  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=11.118625
I20260812 06:16:33.435180  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.037s	user 0.009s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16103,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:33.435784  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.462867  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.463434  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.474208  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.474820  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:33.662326  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.187s	user 0.106s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651904,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1088,"lbm_read_time_us":12737,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31110,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:16:33.662878  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=11.118625
I20260812 06:16:33.708063  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.045s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21675,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:16:33.708600  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.727921  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5347,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.728375  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.739161  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.739717  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:33.894147  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.154s	user 0.115s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651905,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":221,"lbm_read_time_us":10558,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29999,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:16:33.894830  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:33.946444  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.051s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23095,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.946977  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:33.958246  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.958889  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushMRSOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:33.989650  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushMRSOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1496,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1705,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:33.990286  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling LogGCOp(7c918768ff5f4aef9a33625debff18a1): free 132571576 bytes of WAL
I20260812 06:16:33.990566  9248 log_reader.cc:385] T 7c918768ff5f4aef9a33625debff18a1: removed 13 log segments from log reader
I20260812 06:16:33.990625  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000026 (ops 124-128)
I20260812 06:16:33.990671  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000027 (ops 129-133)
I20260812 06:16:33.990710  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000028 (ops 134-138)
I20260812 06:16:33.990754  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000029 (ops 139-143)
I20260812 06:16:33.990792  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000030 (ops 144-148)
I20260812 06:16:33.990828  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000031 (ops 149-152)
I20260812 06:16:33.990870  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000032 (ops 153-157)
I20260812 06:16:33.990907  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000033 (ops 158-162)
I20260812 06:16:33.990945  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000034 (ops 163-167)
I20260812 06:16:33.990983  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000035 (ops 168-172)
I20260812 06:16:33.991019  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000036 (ops 173-177)
I20260812 06:16:33.991057  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000037 (ops 178-182)
I20260812 06:16:33.991094  9248 log.cc:1079] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/7c918768ff5f4aef9a33625debff18a1/wal-000000038 (ops 183-186)
I20260812 06:16:34.020879  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: LogGCOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:34.021370  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=3.181125
I20260812 06:16:34.048637  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.027s	user 0.010s	sys 0.016s Metrics: {"bytes_written":5251341,"delete_count":0,"lbm_write_time_us":6368,"lbm_writes_lt_1ms":131,"mutex_wait_us":77,"reinsert_count":0,"update_count":640}
I20260812 06:16:34.049217  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.196750
I20260812 06:16:34.058255  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3304,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:16:34.058761  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1): 483 bytes on disk
I20260812 06:16:34.059194  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: UndoDeltaBlockGCOp(7c918768ff5f4aef9a33625debff18a1) 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:16:34.059738  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:34.280383  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.220s	user 0.147s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856828,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1488,"lbm_read_time_us":16620,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39101,"lbm_writes_lt_1ms":743,"mutex_wait_us":397,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:16:34.281066  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=14.095187
I20260812 06:16:34.316386  9086 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.132s	user 1.843s	sys 0.122s
I20260812 06:16:34.333823  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.053s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:34.334338  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1): perf score=2.188937
I20260812 06:16:34.344729  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: FlushDeltaMemStoresOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.345136  9345 maintenance_manager.cc:419] P 13104d1d6476473384994f217fc372a8: Scheduling MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1): perf score=1.000000
I20260812 06:16:34.366060  9086 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.001s	sys 0.000s
I20260812 06:16:34.366703  9086 tablet_server.cc:179] TabletServer@127.8.223.129:0 shutting down...
I20260812 06:16:34.481679  9248 maintenance_manager.cc:643] P 13104d1d6476473384994f217fc372a8: MajorDeltaCompactionOp(7c918768ff5f4aef9a33625debff18a1) complete. Timing: real 0.136s	user 0.098s	sys 0.037s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4139495,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512301,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":465,"lbm_read_time_us":8147,"lbm_reads_lt_1ms":518,"lbm_write_time_us":23817,"lbm_writes_lt_1ms":543,"mutex_wait_us":117,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.482719  9086 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.483129  9086 tablet_replica.cc:333] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8: stopping tablet replica
I20260812 06:16:34.483404  9086 raft_consensus.cc:2243] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.483628  9086 raft_consensus.cc:2272] T 7c918768ff5f4aef9a33625debff18a1 P 13104d1d6476473384994f217fc372a8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.499181  9086 tablet_server.cc:196] TabletServer@127.8.223.129:0 shutdown complete.
I20260812 06:16:34.527293  9086 master.cc:562] Master@127.8.223.190:39879 shutting down...
I20260812 06:16:34.531893  9086 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.532092  9086 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.532191  9086 tablet_replica.cc:333] T 00000000000000000000000000000000 P d452a2ddd703466590035dfdc8e39f95: stopping tablet replica
I20260812 06:16:34.545681  9086 master.cc:584] Master@127.8.223.190:39879 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5812 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:34.639212  9086 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.223.190:37009
I20260812 06:16:34.639693  9086 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.641856  9414 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:34.641919  9418 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:34.642020  9086 server_base.cc:1061] running on GCE node
W20260812 06:16:34.642294  9421 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:34.642519  9086 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.642597  9086 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:34.642619  9086 hybrid_clock.cc:648] HybridClock initialized: now 1786515394642619 us; error 0 us; skew 500 ppm
I20260812 06:16:34.643635  9086 webserver.cc:533] Webserver started at http://127.8.223.190:45629/ using document root <none> and password file <none>
I20260812 06:16:34.643774  9086 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.643826  9086 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.643891  9086 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.644234  9086 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/master-0-root/instance:
uuid: "93aecf81442a43f7a300d8c1ed2e5297"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-x4qh"
I20260812 06:16:34.645833  9086 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:34.646795  9429 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.647063  9086 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:34.647128  9086 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/master-0-root
uuid: "93aecf81442a43f7a300d8c1ed2e5297"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-x4qh"
I20260812 06:16:34.647225  9086 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:34.657977  9086 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.658411  9086 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.662813  9086 rpc_server.cc:307] RPC server started. Bound to: 127.8.223.190:37009
I20260812 06:16:34.669871  9534 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:34.670287  9531 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.223.190:37009 every 8 connection(s)
I20260812 06:16:34.681318  9534 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297: Bootstrap starting.
I20260812 06:16:34.682101  9534 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.683128  9534 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297: No bootstrap required, opened a new log
I20260812 06:16:34.683534  9534 raft_consensus.cc:359] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER }
I20260812 06:16:34.683615  9534 raft_consensus.cc:385] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.683638  9534 raft_consensus.cc:740] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 93aecf81442a43f7a300d8c1ed2e5297, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.683743  9534 consensus_queue.cc:260] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [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: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER }
I20260812 06:16:34.683800  9534 raft_consensus.cc:399] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.683823  9534 raft_consensus.cc:493] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.683852  9534 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.684525  9534 raft_consensus.cc:515] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER }
I20260812 06:16:34.684640  9534 leader_election.cc:304] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [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: 93aecf81442a43f7a300d8c1ed2e5297; no voters: 
I20260812 06:16:34.684793  9534 leader_election.cc:290] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.684927  9543 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.685134  9543 raft_consensus.cc:697] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 1 LEADER]: Becoming Leader. State: Replica: 93aecf81442a43f7a300d8c1ed2e5297, State: Running, Role: LEADER
I20260812 06:16:34.685294  9534 sys_catalog.cc:565] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:34.685282  9543 consensus_queue.cc:237] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [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: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER }
I20260812 06:16:34.685786  9544 sys_catalog.cc:455] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "93aecf81442a43f7a300d8c1ed2e5297" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER } }
I20260812 06:16:34.685802  9545 sys_catalog.cc:455] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 93aecf81442a43f7a300d8c1ed2e5297. Latest consensus state: current_term: 1 leader_uuid: "93aecf81442a43f7a300d8c1ed2e5297" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "93aecf81442a43f7a300d8c1ed2e5297" member_type: VOTER } }
I20260812 06:16:34.685899  9545 sys_catalog.cc:458] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:34.686153  9544 sys_catalog.cc:458] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:34.686620  9551 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:34.687603  9551 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:34.687882  9086 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:34.689419  9551 catalog_manager.cc:1383] Generated new cluster ID: 977c2e5eb3fd4967b39367e9a670daf8
I20260812 06:16:34.689486  9551 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:34.695134  9551 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:34.695734  9551 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:34.704244  9551 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297: Generated new TSK 0
I20260812 06:16:34.704447  9551 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:34.720361  9086 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.722389  9579 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:34.722446  9581 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:34.722463  9578 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:34.722697  9086 server_base.cc:1061] running on GCE node
I20260812 06:16:34.722859  9086 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.722908  9086 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:34.722959  9086 hybrid_clock.cc:648] HybridClock initialized: now 1786515394722958 us; error 0 us; skew 500 ppm
I20260812 06:16:34.723902  9086 webserver.cc:533] Webserver started at http://127.8.223.129:35555/ using document root <none> and password file <none>
I20260812 06:16:34.724079  9086 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.724138  9086 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.724220  9086 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.724629  9086 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/instance:
uuid: "aaa3137877b2458694ff6c149b036156"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-x4qh"
I20260812 06:16:34.726225  9086 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:34.727171  9589 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.727465  9086 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:34.727557  9086 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root
uuid: "aaa3137877b2458694ff6c149b036156"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-x4qh"
I20260812 06:16:34.727644  9086 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:34.746199  9086 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.746616  9086 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.746968  9086 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:34.747537  9086 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:34.747599  9086 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.747651  9086 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:34.747712  9086 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.752270  9086 rpc_server.cc:307] RPC server started. Bound to: 127.8.223.129:36759
I20260812 06:16:34.752321  9696 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.223.129:36759 every 8 connection(s)
I20260812 06:16:34.761611  9697 heartbeater.cc:344] Connected to a master server at 127.8.223.190:37009
I20260812 06:16:34.761739  9697 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:34.761963  9697 heartbeater.cc:507] Master 127.8.223.190:37009 requested a full tablet report, sending...
I20260812 06:16:34.762601  9464 ts_manager.cc:194] Registered new tserver with Master: aaa3137877b2458694ff6c149b036156 (127.8.223.129:36759)
I20260812 06:16:34.762672  9086 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009899282s
I20260812 06:16:34.763494  9464 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48722
I20260812 06:16:34.769758  9464 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48726:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:34.778759  9637 tablet_service.cc:1511] Processing CreateTablet for tablet da747c1fb6e54a34a0bfe1b407e11a01 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bf395764a7154ee4b1665c496863be68]), partition=
I20260812 06:16:34.779083  9637 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet da747c1fb6e54a34a0bfe1b407e11a01. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:34.781234  9715 tablet_bootstrap.cc:492] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Bootstrap starting.
I20260812 06:16:34.782105  9715 tablet_bootstrap.cc:654] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.783228  9715 tablet_bootstrap.cc:492] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: No bootstrap required, opened a new log
I20260812 06:16:34.783350  9715 ts_tablet_manager.cc:1403] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:34.783941  9715 raft_consensus.cc:359] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aaa3137877b2458694ff6c149b036156" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 36759 } }
I20260812 06:16:34.784052  9715 raft_consensus.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.784098  9715 raft_consensus.cc:740] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aaa3137877b2458694ff6c149b036156, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.784242  9715 consensus_queue.cc:260] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [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: "aaa3137877b2458694ff6c149b036156" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 36759 } }
I20260812 06:16:34.784370  9715 raft_consensus.cc:399] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.784427  9715 raft_consensus.cc:493] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.784485  9715 raft_consensus.cc:3060] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.785245  9715 raft_consensus.cc:515] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aaa3137877b2458694ff6c149b036156" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 36759 } }
I20260812 06:16:34.785408  9715 leader_election.cc:304] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [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: aaa3137877b2458694ff6c149b036156; no voters: 
I20260812 06:16:34.785629  9715 leader_election.cc:290] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.785733  9719 raft_consensus.cc:2804] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.785987  9715 ts_tablet_manager.cc:1434] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:34.785966  9719 raft_consensus.cc:697] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 1 LEADER]: Becoming Leader. State: Replica: aaa3137877b2458694ff6c149b036156, State: Running, Role: LEADER
I20260812 06:16:34.786038  9697 heartbeater.cc:499] Master 127.8.223.190:37009 was elected leader, sending a full tablet report...
I20260812 06:16:34.786160  9719 consensus_queue.cc:237] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [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: "aaa3137877b2458694ff6c149b036156" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 36759 } }
I20260812 06:16:34.787689  9464 catalog_manager.cc:5719] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 reported cstate change: term changed from 0 to 1, leader changed from <none> to aaa3137877b2458694ff6c149b036156 (127.8.223.129). New cstate: current_term: 1 leader_uuid: "aaa3137877b2458694ff6c149b036156" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aaa3137877b2458694ff6c149b036156" member_type: VOTER last_known_addr { host: "127.8.223.129" port: 36759 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:34.846647  9086 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.016s	sys 0.006s
I20260812 06:16:35.003216  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=19.054940
I20260812 06:16:35.143757  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.140s	user 0.112s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1020,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35858,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:35.144441  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 20290830 bytes of WAL
I20260812 06:16:35.144692  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 2 log segments from log reader
I20260812 06:16:35.144757  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000001 (ops 1-6)
I20260812 06:16:35.144867  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000002 (ops 7-10)
I20260812 06:16:35.150345  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:35.150705  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.176739  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.026s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5459,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.177204  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01): 16411394 bytes on disk
I20260812 06:16:35.177696  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:16:35.178104  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.192889  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.193385  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:35.367704  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.174s	user 0.145s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":829,"lbm_read_time_us":13161,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29736,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":383,"threads_started":5,"update_count":2500}
I20260812 06:16:35.368502  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=11.118625
I20260812 06:16:35.419260  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.051s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":28543,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:35.419742  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.430889  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.431253  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.440568  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.009s	user 0.006s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.440984  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:35.597005  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.156s	user 0.135s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":59,"lbm_read_time_us":9903,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33500,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:16:35.597638  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=11.118625
I20260812 06:16:35.633348  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16174,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:35.633931  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.652595  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.018s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.653087  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:35.774628  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.121s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":7561,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24546,"lbm_writes_lt_1ms":443,"mutex_wait_us":337,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:35.775287  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=10.126437
I20260812 06:16:35.826200  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.051s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.826732  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:35.837857  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.838667  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:35.970806  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.132s	user 0.090s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":9214,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24956,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24704,"update_count":2000}
I20260812 06:16:35.971315  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=10.126437
I20260812 06:16:36.023552  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.052s	user 0.019s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15638,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.024150  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:36.035035  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.035554  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:36.195451  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.160s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":11642,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":443,"mutex_wait_us":305,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":36480,"update_count":2000}
I20260812 06:16:36.196269  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=10.126437
I20260812 06:16:36.242048  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.045s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20950,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.242606  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:36.265756  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.023s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.266337  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:36.281178  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.281651  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:36.447317  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.165s	user 0.121s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":532,"lbm_read_time_us":9924,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33850,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:16:36.449033  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=10.126437
I20260812 06:16:36.482928  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.034s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.483600  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:36.497792  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.498311  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:36.528813  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1761,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:36.529470  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 121006426 bytes of WAL
I20260812 06:16:36.529743  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 12 log segments from log reader
I20260812 06:16:36.529790  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000003 (ops 11-15)
I20260812 06:16:36.529820  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000004 (ops 16-20)
I20260812 06:16:36.529868  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000005 (ops 21-25)
I20260812 06:16:36.529909  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000006 (ops 26-30)
I20260812 06:16:36.529937  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000007 (ops 31-35)
I20260812 06:16:36.529974  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000008 (ops 36-40)
I20260812 06:16:36.530011  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000009 (ops 41-45)
I20260812 06:16:36.530036  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000010 (ops 46-50)
I20260812 06:16:36.530076  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000011 (ops 51-55)
I20260812 06:16:36.530110  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000012 (ops 56-60)
I20260812 06:16:36.530133  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000013 (ops 61-64)
I20260812 06:16:36.530181  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000014 (ops 65-69)
I20260812 06:16:36.558672  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:36.559141  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01): 482 bytes on disk
I20260812 06:16:36.559643  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:16:36.560084  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=6.157687
I20260812 06:16:36.587888  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.028s	user 0.020s	sys 0.003s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":10183,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:36.588385  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 12017932 bytes of WAL
I20260812 06:16:36.588614  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 1 log segments from log reader
I20260812 06:16:36.588677  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000015 (ops 70-74)
I20260812 06:16:36.591787  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:36.592113  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:36.801378  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.209s	user 0.130s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1358,"lbm_read_time_us":14108,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33260,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:16:36.802187  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:36.877628  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.075s	user 0.034s	sys 0.039s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30969,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:36.878337  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:36.898576  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.020s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.899236  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:37.104251  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.205s	user 0.128s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":935,"lbm_read_time_us":13681,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34511,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:16:37.104878  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:37.176329  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.071s	user 0.043s	sys 0.027s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27396,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:37.176892  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:37.202728  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.203282  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:37.213475  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.214032  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:37.461910  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.248s	user 0.190s	sys 0.044s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979635,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":192,"lbm_read_time_us":15044,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41305,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3500}
I20260812 06:16:37.462633  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:37.528786  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.066s	user 0.062s	sys 0.003s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29525,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:37.529265  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:37.542734  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.543201  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:37.739882  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.196s	user 0.123s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1021,"lbm_read_time_us":15026,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35299,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:16:37.740636  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=14.095187
I20260812 06:16:37.800333  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.059s	user 0.043s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24025,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:37.800813  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:37.827148  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5597,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.827730  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:37.843000  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.843619  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:38.013970  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.170s	user 0.106s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":751,"lbm_read_time_us":13084,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35067,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":3000}
I20260812 06:16:38.014750  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=14.095187
I20260812 06:16:38.075506  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.061s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":29961,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.075994  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:38.098122  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.098587  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:38.108814  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.109264  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:38.144258  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1357579,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1407,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1944,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:16:38.144974  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 129320485 bytes of WAL
I20260812 06:16:38.145217  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 13 log segments from log reader
I20260812 06:16:38.145267  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000016 (ops 75-79)
I20260812 06:16:38.145318  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000017 (ops 80-84)
I20260812 06:16:38.145360  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000018 (ops 85-88)
I20260812 06:16:38.145402  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000019 (ops 89-93)
I20260812 06:16:38.145439  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000020 (ops 94-98)
I20260812 06:16:38.145462  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000021 (ops 99-102)
I20260812 06:16:38.145503  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000022 (ops 103-107)
I20260812 06:16:38.145542  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000023 (ops 108-112)
I20260812 06:16:38.145581  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000024 (ops 113-117)
I20260812 06:16:38.145618  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000025 (ops 118-122)
I20260812 06:16:38.145656  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000026 (ops 123-127)
I20260812 06:16:38.145702  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000027 (ops 128-132)
I20260812 06:16:38.145740  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000028 (ops 133-137)
I20260812 06:16:38.175175  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:38.175581  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=5.165500
I20260812 06:16:38.192804  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":7015375,"delete_count":0,"lbm_write_time_us":7051,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:16:38.193439  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01): 507 bytes on disk
I20260812 06:16:38.194010  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:16:38.194638  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:38.202473  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.008s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:16:38.202884  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:38.400889  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.198s	user 0.145s	sys 0.051s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082208,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1803,"lbm_read_time_us":13877,"lbm_reads_lt_1ms":871,"lbm_write_time_us":41968,"lbm_writes_lt_1ms":843,"mutex_wait_us":410,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":98,"threads_started":1,"update_count":4000}
I20260812 06:16:38.401660  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:38.463572  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.062s	user 0.041s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27747,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:38.464123  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:38.487953  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.024s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.488519  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:38.689621  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.201s	user 0.112s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":13017,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35237,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:38.690304  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:38.776088  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.086s	user 0.034s	sys 0.051s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":36927,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:38.776563  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=3.181125
I20260812 06:16:38.799186  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.022s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5767,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:38.799671  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:38.809291  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3685,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:38.809762  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:39.031891  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.222s	user 0.138s	sys 0.083s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979627,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":121,"lbm_read_time_us":16215,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39294,"lbm_writes_lt_1ms":743,"mutex_wait_us":70,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":3500}
I20260812 06:16:39.034621  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:39.101663  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.066s	user 0.047s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31497,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:39.102157  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=3.181125
I20260812 06:16:39.123965  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5488,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:39.124464  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:39.134267  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.134754  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:39.362608  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.228s	user 0.148s	sys 0.076s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979623,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":712,"lbm_read_time_us":15796,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43990,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:16:39.363407  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=18.063937
I20260812 06:16:39.420449  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.057s	user 0.032s	sys 0.024s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25758,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:39.421190  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:39.438674  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.439190  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:39.490065  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushMRSOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.051s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1395,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2181,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:39.490854  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 112239611 bytes of WAL
I20260812 06:16:39.491117  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 11 log segments from log reader
I20260812 06:16:39.491179  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000029 (ops 138-142)
I20260812 06:16:39.491216  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000030 (ops 143-147)
I20260812 06:16:39.491251  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000031 (ops 148-152)
I20260812 06:16:39.491285  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000032 (ops 153-156)
I20260812 06:16:39.491317  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000033 (ops 157-161)
I20260812 06:16:39.491343  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000034 (ops 162-166)
I20260812 06:16:39.491405  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000035 (ops 167-171)
I20260812 06:16:39.491438  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000036 (ops 172-176)
I20260812 06:16:39.491466  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000037 (ops 177-181)
I20260812 06:16:39.491497  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000038 (ops 182-186)
I20260812 06:16:39.491523  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000039 (ops 187-191)
I20260812 06:16:39.521279  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:39.521785  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=6.157687
I20260812 06:16:39.553750  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.032s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12398,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:39.554256  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01): free 8767145 bytes of WAL
I20260812 06:16:39.554471  9599 log_reader.cc:385] T da747c1fb6e54a34a0bfe1b407e11a01: removed 1 log segments from log reader
I20260812 06:16:39.554517  9599 log.cc:1079] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: Deleting log segment in path: /tmp/dist-test-taskGJfqm2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515388816862-9086-0/minicluster-data/ts-0-root/wals/da747c1fb6e54a34a0bfe1b407e11a01/wal-000000040 (ops 192-196)
I20260812 06:16:39.556391  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: LogGCOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:39.556716  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=2.188937
I20260812 06:16:39.567446  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: FlushDeltaMemStoresOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.011s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.567902  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01): 462 bytes on disk
I20260812 06:16:39.568341  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: UndoDeltaBlockGCOp(da747c1fb6e54a34a0bfe1b407e11a01) 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:16:39.569304  9698 maintenance_manager.cc:419] P aaa3137877b2458694ff6c149b036156: Scheduling MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01): perf score=1.000000
I20260812 06:16:39.603315  9086 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.757s	user 1.791s	sys 0.144s
I20260812 06:16:39.705467  9086 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.000s	sys 0.001s
I20260812 06:16:39.705992  9086 tablet_server.cc:179] TabletServer@127.8.223.129:0 shutting down...
I20260812 06:16:39.781041  9599 maintenance_manager.cc:643] P aaa3137877b2458694ff6c149b036156: MajorDeltaCompactionOp(da747c1fb6e54a34a0bfe1b407e11a01) complete. Timing: real 0.212s	user 0.155s	sys 0.056s Metrics: {"cfile_cache_miss":934,"cfile_cache_miss_bytes":41184575,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1868,"lbm_read_time_us":19267,"lbm_reads_lt_1ms":970,"lbm_write_time_us":42466,"lbm_writes_lt_1ms":943,"mutex_wait_us":365,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":84,"threads_started":1,"update_count":4500}
I20260812 06:16:39.783723  9086 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:39.784024  9086 tablet_replica.cc:333] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156: stopping tablet replica
I20260812 06:16:39.784207  9086 raft_consensus.cc:2243] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:39.784423  9086 raft_consensus.cc:2272] T da747c1fb6e54a34a0bfe1b407e11a01 P aaa3137877b2458694ff6c149b036156 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:39.789937  9086 tablet_server.cc:196] TabletServer@127.8.223.129:0 shutdown complete.
I20260812 06:16:39.869298  9086 master.cc:562] Master@127.8.223.190:37009 shutting down...
I20260812 06:16:39.872737  9086 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:39.872982  9086 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:39.873073  9086 tablet_replica.cc:333] T 00000000000000000000000000000000 P 93aecf81442a43f7a300d8c1ed2e5297: stopping tablet replica
I20260812 06:16:39.885746  9086 master.cc:584] Master@127.8.223.190:37009 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5335 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11148 ms total)

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