[==========] 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:20:22.474840  5301 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.45.126:41361
I20260812 06:20:22.475864  5301 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:20:22.476466  5301 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.483592  5310 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:20:22.483729  5301 server_base.cc:1061] running on GCE node
W20260812 06:20:22.483596  5308 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:20:22.483968  5307 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:20:22.484475  5301 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.484622  5301 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:20:22.484673  5301 hybrid_clock.cc:648] HybridClock initialized: now 1786515622484670 us; error 0 us; skew 500 ppm
I20260812 06:20:22.486523  5301 webserver.cc:533] Webserver started at http://127.5.45.126:33825/ using document root <none> and password file <none>
I20260812 06:20:22.487071  5301 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.487159  5301 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.487423  5301 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.489235  5301 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/master-0-root/instance:
uuid: "fa973476a70045aeb7db2c5ec43409c2"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-9gcw"
I20260812 06:20:22.492726  5301 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:20:22.494872  5316 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:20:22.495857  5301 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:22.495992  5301 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/master-0-root
uuid: "fa973476a70045aeb7db2c5ec43409c2"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-9gcw"
I20260812 06:20:22.496097  5301 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-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:20:22.515062  5301 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.515758  5301 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:20:22.515964  5301 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.524021  5301 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.126:41361
I20260812 06:20:22.524031  5378 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.126:41361 every 8 connection(s)
I20260812 06:20:22.526301  5379 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:20:22.531565  5379 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: Bootstrap starting.
I20260812 06:20:22.533802  5379 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.534647  5379 log.cc:826] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:22.536453  5379 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: No bootstrap required, opened a new log
I20260812 06:20:22.539208  5379 raft_consensus.cc:359] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER }
I20260812 06:20:22.539364  5379 raft_consensus.cc:385] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.539404  5379 raft_consensus.cc:740] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fa973476a70045aeb7db2c5ec43409c2, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.539909  5379 consensus_queue.cc:260] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [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: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER }
I20260812 06:20:22.540033  5379 raft_consensus.cc:399] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.540078  5379 raft_consensus.cc:493] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.540174  5379 raft_consensus.cc:3060] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.540985  5379 raft_consensus.cc:515] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER }
I20260812 06:20:22.541460  5379 leader_election.cc:304] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [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: fa973476a70045aeb7db2c5ec43409c2; no voters: 
I20260812 06:20:22.541723  5379 leader_election.cc:290] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.541867  5383 raft_consensus.cc:2804] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.542140  5383 raft_consensus.cc:697] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 1 LEADER]: Becoming Leader. State: Replica: fa973476a70045aeb7db2c5ec43409c2, State: Running, Role: LEADER
I20260812 06:20:22.542558  5383 consensus_queue.cc:237] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [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: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER }
I20260812 06:20:22.542781  5379 sys_catalog.cc:565] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.544588  5386 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader fa973476a70045aeb7db2c5ec43409c2. Latest consensus state: current_term: 1 leader_uuid: "fa973476a70045aeb7db2c5ec43409c2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER } }
I20260812 06:20:22.544569  5385 sys_catalog.cc:455] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "fa973476a70045aeb7db2c5ec43409c2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fa973476a70045aeb7db2c5ec43409c2" member_type: VOTER } }
I20260812 06:20:22.544719  5386 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.544720  5385 sys_catalog.cc:458] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.545033  5301 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:22.547392  5400 catalog_manager.cc:1594] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:22.547483  5400 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:22.547562  5399 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.548287  5399 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.553355  5399 catalog_manager.cc:1383] Generated new cluster ID: 544bdea169e04dad9ef92f067741a75c
I20260812 06:20:22.553428  5399 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.566545  5399 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.567402  5399 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.574672  5399 catalog_manager.cc:6092] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: Generated new TSK 0
I20260812 06:20:22.575278  5399 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.577703  5301 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.580572  5407 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:20:22.580649  5408 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:20:22.580698  5410 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:20:22.580962  5301 server_base.cc:1061] running on GCE node
I20260812 06:20:22.581198  5301 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.581256  5301 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:20:22.581274  5301 hybrid_clock.cc:648] HybridClock initialized: now 1786515622581274 us; error 0 us; skew 500 ppm
I20260812 06:20:22.582216  5301 webserver.cc:533] Webserver started at http://127.5.45.65:32959/ using document root <none> and password file <none>
I20260812 06:20:22.582402  5301 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.582455  5301 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.582566  5301 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.582976  5301 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/instance:
uuid: "0c88e792b7e54039a4eeab925746210b"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-9gcw"
I20260812 06:20:22.584548  5301 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:22.585675  5416 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:20:22.585942  5301 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:22.586035  5301 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root
uuid: "0c88e792b7e54039a4eeab925746210b"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-9gcw"
I20260812 06:20:22.586131  5301 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-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:20:22.595243  5301 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.595722  5301 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.596285  5301 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.597184  5301 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.597272  5301 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.597352  5301 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.597388  5301 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.604660  5301 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.65:46569
I20260812 06:20:22.604693  5493 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.65:46569 every 8 connection(s)
I20260812 06:20:22.615123  5494 heartbeater.cc:344] Connected to a master server at 127.5.45.126:41361
I20260812 06:20:22.615418  5494 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.615922  5494 heartbeater.cc:507] Master 127.5.45.126:41361 requested a full tablet report, sending...
I20260812 06:20:22.617553  5334 ts_manager.cc:194] Registered new tserver with Master: 0c88e792b7e54039a4eeab925746210b (127.5.45.65:46569)
I20260812 06:20:22.617790  5301 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01237046s
I20260812 06:20:22.619113  5334 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55444
I20260812 06:20:22.628702  5334 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55454:
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:20:22.646108  5448 tablet_service.cc:1511] Processing CreateTablet for tablet c2ee323f89834a5fb10e19f0c7eaba7d (DEFAULT_TABLE table=heavy-update-compaction-test [id=2ec4debfffa14440b9d5cb6f5d393c16]), partition=
I20260812 06:20:22.646667  5448 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c2ee323f89834a5fb10e19f0c7eaba7d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.649335  5507 tablet_bootstrap.cc:492] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Bootstrap starting.
I20260812 06:20:22.650473  5507 tablet_bootstrap.cc:654] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.651746  5507 tablet_bootstrap.cc:492] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: No bootstrap required, opened a new log
I20260812 06:20:22.651850  5507 ts_tablet_manager.cc:1403] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:22.652357  5507 raft_consensus.cc:359] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c88e792b7e54039a4eeab925746210b" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 46569 } }
I20260812 06:20:22.652482  5507 raft_consensus.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.652516  5507 raft_consensus.cc:740] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0c88e792b7e54039a4eeab925746210b, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.652657  5507 consensus_queue.cc:260] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [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: "0c88e792b7e54039a4eeab925746210b" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 46569 } }
I20260812 06:20:22.652765  5507 raft_consensus.cc:399] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.652803  5507 raft_consensus.cc:493] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.652851  5507 raft_consensus.cc:3060] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.653833  5507 raft_consensus.cc:515] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c88e792b7e54039a4eeab925746210b" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 46569 } }
I20260812 06:20:22.653983  5507 leader_election.cc:304] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [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: 0c88e792b7e54039a4eeab925746210b; no voters: 
I20260812 06:20:22.654199  5507 leader_election.cc:290] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.654385  5509 raft_consensus.cc:2804] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.654549  5507 ts_tablet_manager.cc:1434] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:22.654675  5509 raft_consensus.cc:697] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 1 LEADER]: Becoming Leader. State: Replica: 0c88e792b7e54039a4eeab925746210b, State: Running, Role: LEADER
I20260812 06:20:22.654815  5494 heartbeater.cc:499] Master 127.5.45.126:41361 was elected leader, sending a full tablet report...
I20260812 06:20:22.654893  5509 consensus_queue.cc:237] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [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: "0c88e792b7e54039a4eeab925746210b" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 46569 } }
I20260812 06:20:22.657855  5339 catalog_manager.cc:5719] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b reported cstate change: term changed from 0 to 1, leader changed from <none> to 0c88e792b7e54039a4eeab925746210b (127.5.45.65). New cstate: current_term: 1 leader_uuid: "0c88e792b7e54039a4eeab925746210b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c88e792b7e54039a4eeab925746210b" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 46569 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.722442  5301 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.007s
I20260812 06:20:22.855926  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=19.054940
I20260812 06:20:23.049247  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.193s	user 0.140s	sys 0.052s Metrics: {"bytes_written":13168992,"cfile_init":1,"compiler_manager_pool.queue_time_us":193,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":874,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48360,"lbm_writes_lt_1ms":778,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":125,"threads_started":1,"update_count":1605}
I20260812 06:20:23.050628  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): free 20743880 bytes of WAL
I20260812 06:20:23.050971  5421 log_reader.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d: removed 2 log segments from log reader
I20260812 06:20:23.051044  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000001 (ops 1-6)
I20260812 06:20:23.051110  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000002 (ops 7-11)
I20260812 06:20:23.057227  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:20:23.057873  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=5.165500
I20260812 06:20:23.087468  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.029s	user 0.016s	sys 0.010s Metrics: {"bytes_written":6441042,"delete_count":0,"lbm_write_time_us":9603,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:20:23.088073  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): 16411392 bytes on disk
I20260812 06:20:23.088840  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.089411  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:23.280344  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.191s	user 0.139s	sys 0.041s Metrics: {"cfile_cache_miss":510,"cfile_cache_miss_bytes":23872156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1192,"lbm_read_time_us":12443,"lbm_reads_lt_1ms":542,"lbm_write_time_us":30311,"lbm_writes_lt_1ms":521,"mutex_wait_us":47,"peak_mem_usage":60132362,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":370,"threads_started":5,"update_count":2390}
I20260812 06:20:23.280906  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=15.087375
I20260812 06:20:23.332403  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.051s	user 0.034s	sys 0.013s Metrics: {"bytes_written":17312440,"delete_count":0,"lbm_write_time_us":22550,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:20:23.332855  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:23.344277  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.344877  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:23.509411  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.164s	user 0.111s	sys 0.046s Metrics: {"cfile_cache_miss":554,"cfile_cache_miss_bytes":25677227,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":9507,"lbm_reads_lt_1ms":594,"lbm_write_time_us":29267,"lbm_writes_lt_1ms":565,"mutex_wait_us":40,"peak_mem_usage":65059054,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2610}
I20260812 06:20:23.510068  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=11.118625
I20260812 06:20:23.547178  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16119,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:23.547787  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:23.563884  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5274,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.564397  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:23.690874  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":422,"lbm_read_time_us":9188,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25538,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:20:23.691552  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=10.126437
I20260812 06:20:23.734638  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.043s	user 0.026s	sys 0.003s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13308,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.735215  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:23.747359  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.747997  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:23.884830  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.137s	user 0.096s	sys 0.040s 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":2192,"lbm_read_time_us":9077,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28672,"lbm_writes_lt_1ms":443,"mutex_wait_us":519,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.885370  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=10.126437
I20260812 06:20:23.931361  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.046s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15455,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.931923  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:23.942656  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4133,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.943156  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:24.088275  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.145s	user 0.100s	sys 0.043s 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":166,"lbm_read_time_us":11580,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25371,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:20:24.088742  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=10.126437
I20260812 06:20:24.141310  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.052s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17582,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.141809  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:24.155427  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.156175  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:24.283638  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.127s	user 0.086s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3399,"lbm_read_time_us":8146,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24310,"lbm_writes_lt_1ms":443,"mutex_wait_us":1341,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:24.284451  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=10.126437
I20260812 06:20:24.329753  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.045s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22264,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.330265  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:24.344393  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.344861  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:24.370609  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.026s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1631,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1514,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:24.371417  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): free 120553397 bytes of WAL
I20260812 06:20:24.371666  5421 log_reader.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d: removed 12 log segments from log reader
I20260812 06:20:24.371712  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000003 (ops 12-16)
I20260812 06:20:24.371742  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000004 (ops 17-21)
I20260812 06:20:24.371811  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000005 (ops 22-26)
I20260812 06:20:24.371881  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000006 (ops 27-30)
I20260812 06:20:24.371919  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000007 (ops 31-35)
I20260812 06:20:24.371963  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000008 (ops 36-40)
I20260812 06:20:24.372004  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000009 (ops 41-45)
I20260812 06:20:24.372044  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000010 (ops 46-50)
I20260812 06:20:24.372085  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000011 (ops 51-54)
I20260812 06:20:24.372126  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000012 (ops 55-59)
I20260812 06:20:24.372165  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000013 (ops 60-64)
I20260812 06:20:24.372205  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000014 (ops 65-69)
I20260812 06:20:24.399847  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:24.400437  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): 472 bytes on disk
I20260812 06:20:24.400964  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) 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:20:24.401455  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=4.173312
I20260812 06:20:24.415840  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":5497488,"delete_count":0,"lbm_write_time_us":5829,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:20:24.416311  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.196750
I20260812 06:20:24.425004  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.009s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2712,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:20:24.425583  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:24.602694  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.177s	user 0.124s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877308,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":207,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36088,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:20:24.603222  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:24.658437  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.055s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25751,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.658998  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:24.674734  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.675426  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:24.828413  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.153s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":706,"lbm_read_time_us":9482,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31328,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:24.829035  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=11.118625
I20260812 06:20:24.873386  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.044s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18876,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.873876  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:24.887290  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4555,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.887890  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:25.052134  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.164s	user 0.112s	sys 0.040s 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":791,"lbm_read_time_us":9624,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25945,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:20:25.052801  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:25.109526  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.057s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21709,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.110131  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.122232  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.122723  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:25.298312  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.175s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1156,"lbm_read_time_us":12799,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28980,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2500}
I20260812 06:20:25.298947  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:25.359920  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.061s	user 0.020s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.360466  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.371435  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4231,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.371935  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:25.554540  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.182s	user 0.109s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":12192,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28212,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:20:25.555167  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:25.619462  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.064s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25281,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.620152  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.631026  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.631577  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:25.807165  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.175s	user 0.124s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":383,"lbm_read_time_us":12924,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30268,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:20:25.808027  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=11.118625
I20260812 06:20:25.839056  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.031s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13282,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:25.839941  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.868642  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.028s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5555,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.869252  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.880106  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.880951  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:25.920367  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.039s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":332,"dirs.run_wall_time_us":1646,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2201,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:25.921211  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): free 124710309 bytes of WAL
I20260812 06:20:25.921471  5421 log_reader.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d: removed 12 log segments from log reader
I20260812 06:20:25.921546  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000015 (ops 70-74)
I20260812 06:20:25.921589  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000016 (ops 75-79)
I20260812 06:20:25.921622  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000017 (ops 80-84)
I20260812 06:20:25.921651  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000018 (ops 85-89)
I20260812 06:20:25.921684  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000019 (ops 90-94)
I20260812 06:20:25.921718  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000020 (ops 95-99)
I20260812 06:20:25.921751  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000021 (ops 100-104)
I20260812 06:20:25.921789  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000022 (ops 105-109)
I20260812 06:20:25.921825  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000023 (ops 110-114)
I20260812 06:20:25.921859  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000024 (ops 115-119)
I20260812 06:20:25.921895  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000025 (ops 120-124)
I20260812 06:20:25.921924  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000026 (ops 125-129)
I20260812 06:20:25.953176  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:25.953814  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): 481 bytes on disk
I20260812 06:20:25.954556  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.955513  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:25.971721  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.972218  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): free 12017954 bytes of WAL
I20260812 06:20:25.972441  5421 log_reader.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d: removed 1 log segments from log reader
I20260812 06:20:25.972484  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000027 (ops 130-134)
I20260812 06:20:25.974857  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:25.975157  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:26.176667  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.201s	user 0.154s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1598,"lbm_read_time_us":13257,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37107,"lbm_writes_lt_1ms":643,"mutex_wait_us":970,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":46976,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:20:26.177402  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=15.087375
I20260812 06:20:26.247692  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.070s	user 0.015s	sys 0.041s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":27360,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:20:26.248214  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=6.157687
I20260812 06:20:26.270293  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.022s	user 0.013s	sys 0.007s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8819,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:26.271057  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:26.497035  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.226s	user 0.149s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":587,"lbm_read_time_us":13693,"lbm_reads_lt_1ms":664,"lbm_write_time_us":39556,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":3000}
I20260812 06:20:26.497666  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=18.063937
I20260812 06:20:26.569366  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.072s	user 0.038s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26478,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.569832  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:26.580793  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.581651  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:26.787820  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.206s	user 0.132s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":12603,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33693,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:26.789721  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=16.079562
I20260812 06:20:26.843533  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.054s	user 0.041s	sys 0.008s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":22840,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:20:26.844043  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:26.862761  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":5672,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:20:26.863278  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:26.873903  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.874678  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:27.084463  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.209s	user 0.159s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":857,"lbm_read_time_us":15639,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37951,"lbm_writes_lt_1ms":643,"mutex_wait_us":273,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:27.085242  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:27.136297  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.051s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22833,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.136895  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:27.148298  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.148754  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:27.321064  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.172s	user 0.092s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":12008,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27841,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:27.321794  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:27.381842  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.060s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20306,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.382478  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:27.395561  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.396124  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:27.431490  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushMRSOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1504,"drs_written":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2159,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:27.432202  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): free 108988750 bytes of WAL
I20260812 06:20:27.432442  5421 log_reader.cc:385] T c2ee323f89834a5fb10e19f0c7eaba7d: removed 11 log segments from log reader
I20260812 06:20:27.432489  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000028 (ops 135-139)
I20260812 06:20:27.432518  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000029 (ops 140-144)
I20260812 06:20:27.432570  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000030 (ops 145-149)
I20260812 06:20:27.432614  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000031 (ops 150-154)
I20260812 06:20:27.432677  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000032 (ops 155-159)
I20260812 06:20:27.432717  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000033 (ops 160-164)
I20260812 06:20:27.432766  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000034 (ops 165-168)
I20260812 06:20:27.432806  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000035 (ops 169-173)
I20260812 06:20:27.432843  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000036 (ops 174-178)
I20260812 06:20:27.432885  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000037 (ops 179-183)
I20260812 06:20:27.432927  5421 log.cc:1079] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/c2ee323f89834a5fb10e19f0c7eaba7d/wal-000000038 (ops 184-188)
I20260812 06:20:27.456724  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: LogGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:27.457226  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=3.181125
I20260812 06:20:27.481455  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.024s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7253,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:27.481935  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d): 461 bytes on disk
I20260812 06:20:27.482358  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: UndoDeltaBlockGCOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.482899  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=2.188937
I20260812 06:20:27.493708  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.494400  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=1.000000
I20260812 06:20:27.674686  5301 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.952s	user 1.882s	sys 0.114s
I20260812 06:20:27.705006  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: MajorDeltaCompactionOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.210s	user 0.121s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15867,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38673,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3500}
I20260812 06:20:27.705659  5495 maintenance_manager.cc:419] P 0c88e792b7e54039a4eeab925746210b: Scheduling FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d): perf score=14.095187
I20260812 06:20:27.744540  5301 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.069s	user 0.001s	sys 0.000s
I20260812 06:20:27.745275  5301 tablet_server.cc:179] TabletServer@127.5.45.65:0 shutting down...
I20260812 06:20:27.785516  5421 maintenance_manager.cc:643] P 0c88e792b7e54039a4eeab925746210b: FlushDeltaMemStoresOp(c2ee323f89834a5fb10e19f0c7eaba7d) complete. Timing: real 0.080s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.786183  5301 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.786630  5301 tablet_replica.cc:333] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b: stopping tablet replica
I20260812 06:20:27.787014  5301 raft_consensus.cc:2243] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.787281  5301 raft_consensus.cc:2272] T c2ee323f89834a5fb10e19f0c7eaba7d P 0c88e792b7e54039a4eeab925746210b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.802896  5301 tablet_server.cc:196] TabletServer@127.5.45.65:0 shutdown complete.
I20260812 06:20:27.807690  5301 master.cc:562] Master@127.5.45.126:41361 shutting down...
I20260812 06:20:27.812114  5301 raft_consensus.cc:2243] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.812294  5301 raft_consensus.cc:2272] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.812374  5301 tablet_replica.cc:333] T 00000000000000000000000000000000 P fa973476a70045aeb7db2c5ec43409c2: stopping tablet replica
I20260812 06:20:27.824841  5301 master.cc:584] Master@127.5.45.126:41361 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5438 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:27.913118  5301 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.45.126:40831
I20260812 06:20:27.913591  5301 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:27.915920  5530 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:20:27.916046  5533 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:20:27.916100  5301 server_base.cc:1061] running on GCE node
W20260812 06:20:27.916071  5529 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:20:27.916471  5301 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:27.916518  5301 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:20:27.916534  5301 hybrid_clock.cc:648] HybridClock initialized: now 1786515627916534 us; error 0 us; skew 500 ppm
I20260812 06:20:27.917430  5301 webserver.cc:533] Webserver started at http://127.5.45.126:42771/ using document root <none> and password file <none>
I20260812 06:20:27.917606  5301 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:27.917686  5301 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:27.917771  5301 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:27.918167  5301 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/master-0-root/instance:
uuid: "bb3f63a39272411d9a7a129eeac800e7"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-9gcw"
I20260812 06:20:27.919790  5301 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:27.920755  5538 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:20:27.921039  5301 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:27.921106  5301 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/master-0-root
uuid: "bb3f63a39272411d9a7a129eeac800e7"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-9gcw"
I20260812 06:20:27.921260  5301 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-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:20:27.928428  5301 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:27.928745  5301 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:27.932578  5301 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.126:40831
I20260812 06:20:27.935664  5600 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.126:40831 every 8 connection(s)
I20260812 06:20:27.936139  5601 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:20:27.949690  5601 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7: Bootstrap starting.
I20260812 06:20:27.950603  5601 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:27.951747  5601 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7: No bootstrap required, opened a new log
I20260812 06:20:27.952221  5601 raft_consensus.cc:359] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER }
I20260812 06:20:27.952314  5601 raft_consensus.cc:385] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:27.952382  5601 raft_consensus.cc:740] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb3f63a39272411d9a7a129eeac800e7, State: Initialized, Role: FOLLOWER
I20260812 06:20:27.952572  5601 consensus_queue.cc:260] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [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: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER }
I20260812 06:20:27.952647  5601 raft_consensus.cc:399] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:27.952706  5601 raft_consensus.cc:493] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:27.952768  5601 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:27.953537  5601 raft_consensus.cc:515] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER }
I20260812 06:20:27.953689  5601 leader_election.cc:304] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [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: bb3f63a39272411d9a7a129eeac800e7; no voters: 
I20260812 06:20:27.953918  5601 leader_election.cc:290] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:27.954051  5604 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:27.954244  5604 raft_consensus.cc:697] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 1 LEADER]: Becoming Leader. State: Replica: bb3f63a39272411d9a7a129eeac800e7, State: Running, Role: LEADER
I20260812 06:20:27.954437  5601 sys_catalog.cc:565] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:27.954458  5604 consensus_queue.cc:237] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [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: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER }
I20260812 06:20:27.954933  5605 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bb3f63a39272411d9a7a129eeac800e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER } }
I20260812 06:20:27.954958  5606 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bb3f63a39272411d9a7a129eeac800e7. Latest consensus state: current_term: 1 leader_uuid: "bb3f63a39272411d9a7a129eeac800e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb3f63a39272411d9a7a129eeac800e7" member_type: VOTER } }
I20260812 06:20:27.955098  5605 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:27.955152  5606 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:27.955595  5612 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:27.956408  5612 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:27.956650  5301 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:27.958215  5612 catalog_manager.cc:1383] Generated new cluster ID: cac6ac6f95a8448a8397ba9ce01e39ba
I20260812 06:20:27.958276  5612 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:27.985870  5612 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:27.986500  5612 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:27.995002  5612 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7: Generated new TSK 0
I20260812 06:20:27.995213  5612 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:28.021369  5301 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.023633  5624 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:20:28.023785  5301 server_base.cc:1061] running on GCE node
W20260812 06:20:28.023633  5625 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:20:28.023732  5628 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:20:28.024137  5301 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.024181  5301 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:20:28.024199  5301 hybrid_clock.cc:648] HybridClock initialized: now 1786515628024199 us; error 0 us; skew 500 ppm
I20260812 06:20:28.025095  5301 webserver.cc:533] Webserver started at http://127.5.45.65:45615/ using document root <none> and password file <none>
I20260812 06:20:28.025297  5301 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.025347  5301 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.025400  5301 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.025758  5301 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/instance:
uuid: "5aaaae89940043e6b38e8675b3c69054"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-9gcw"
I20260812 06:20:28.027215  5301 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:28.028103  5633 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:20:28.028352  5301 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:28.028414  5301 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root
uuid: "5aaaae89940043e6b38e8675b3c69054"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-9gcw"
I20260812 06:20:28.028468  5301 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-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:20:28.046741  5301 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.047142  5301 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.047429  5301 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:28.047955  5301 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:28.047996  5301 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.048064  5301 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:28.048106  5301 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.052903  5301 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.65:33751
I20260812 06:20:28.052980  5706 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.65:33751 every 8 connection(s)
I20260812 06:20:28.063366  5707 heartbeater.cc:344] Connected to a master server at 127.5.45.126:40831
I20260812 06:20:28.063513  5707 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:28.063774  5707 heartbeater.cc:507] Master 127.5.45.126:40831 requested a full tablet report, sending...
I20260812 06:20:28.064472  5555 ts_manager.cc:194] Registered new tserver with Master: 5aaaae89940043e6b38e8675b3c69054 (127.5.45.65:33751)
I20260812 06:20:28.064512  5301 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011064502s
I20260812 06:20:28.065534  5555 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35794
I20260812 06:20:28.071728  5555 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35798:
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:20:28.080259  5665 tablet_service.cc:1511] Processing CreateTablet for tablet 122b888fbbe34096bb6b0a7948642c02 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7ee06c82c25a41219483e551b6f8020b]), partition=
I20260812 06:20:28.080531  5665 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 122b888fbbe34096bb6b0a7948642c02. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:28.082643  5719 tablet_bootstrap.cc:492] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Bootstrap starting.
I20260812 06:20:28.083621  5719 tablet_bootstrap.cc:654] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.084728  5719 tablet_bootstrap.cc:492] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: No bootstrap required, opened a new log
I20260812 06:20:28.084861  5719 ts_tablet_manager.cc:1403] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:28.085382  5719 raft_consensus.cc:359] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5aaaae89940043e6b38e8675b3c69054" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 33751 } }
I20260812 06:20:28.085497  5719 raft_consensus.cc:385] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.085547  5719 raft_consensus.cc:740] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5aaaae89940043e6b38e8675b3c69054, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.085697  5719 consensus_queue.cc:260] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [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: "5aaaae89940043e6b38e8675b3c69054" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 33751 } }
I20260812 06:20:28.085807  5719 raft_consensus.cc:399] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.085848  5719 raft_consensus.cc:493] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.085907  5719 raft_consensus.cc:3060] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.086705  5719 raft_consensus.cc:515] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5aaaae89940043e6b38e8675b3c69054" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 33751 } }
I20260812 06:20:28.086865  5719 leader_election.cc:304] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [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: 5aaaae89940043e6b38e8675b3c69054; no voters: 
I20260812 06:20:28.087090  5719 leader_election.cc:290] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.087219  5721 raft_consensus.cc:2804] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.087436  5719 ts_tablet_manager.cc:1434] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:28.087457  5707 heartbeater.cc:499] Master 127.5.45.126:40831 was elected leader, sending a full tablet report...
I20260812 06:20:28.087466  5721 raft_consensus.cc:697] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 1 LEADER]: Becoming Leader. State: Replica: 5aaaae89940043e6b38e8675b3c69054, State: Running, Role: LEADER
I20260812 06:20:28.087725  5721 consensus_queue.cc:237] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [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: "5aaaae89940043e6b38e8675b3c69054" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 33751 } }
I20260812 06:20:28.089198  5555 catalog_manager.cc:5719] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5aaaae89940043e6b38e8675b3c69054 (127.5.45.65). New cstate: current_term: 1 leader_uuid: "5aaaae89940043e6b38e8675b3c69054" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5aaaae89940043e6b38e8675b3c69054" member_type: VOTER last_known_addr { host: "127.5.45.65" port: 33751 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:28.151278  5301 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.012s	sys 0.010s
I20260812 06:20:28.304060  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushMRSOp(122b888fbbe34096bb6b0a7948642c02): perf score=19.054940
I20260812 06:20:28.446913  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushMRSOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.143s	user 0.106s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":869,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37955,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:28.447512  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling LogGCOp(122b888fbbe34096bb6b0a7948642c02): free 20290830 bytes of WAL
I20260812 06:20:28.447741  5640 log_reader.cc:385] T 122b888fbbe34096bb6b0a7948642c02: removed 2 log segments from log reader
I20260812 06:20:28.447786  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000001 (ops 1-6)
I20260812 06:20:28.447817  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000002 (ops 7-10)
I20260812 06:20:28.451967  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: LogGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:28.452293  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:28.472208  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.472781  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:28.628785  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.156s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":888,"lbm_read_time_us":9205,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26833,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":339,"threads_started":5,"update_count":2000}
I20260812 06:20:28.629575  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02): 16411393 bytes on disk
I20260812 06:20:28.629972  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.630364  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:28.678665  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.679132  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:28.689725  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.690335  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:28.857543  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.167s	user 0.112s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1267,"lbm_read_time_us":10338,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29585,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:20:28.858220  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=12.110812
I20260812 06:20:28.904174  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.046s	user 0.022s	sys 0.020s Metrics: {"bytes_written":13784351,"delete_count":0,"lbm_write_time_us":19183,"lbm_writes_lt_1ms":339,"reinsert_count":0,"update_count":1680}
I20260812 06:20:28.904733  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.196750
I20260812 06:20:28.925876  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.021s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":3035,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:20:28.928017  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:28.938792  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.939265  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:29.115433  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.176s	user 0.110s	sys 0.057s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774765,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":120,"lbm_read_time_us":12384,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27333,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:20:29.116074  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:29.177085  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.061s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23608,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.177677  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:29.187973  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.188393  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:29.365792  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.177s	user 0.118s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":12012,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30827,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:20:29.366443  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:29.427704  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.061s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22808,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.428339  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:29.446431  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.447093  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:29.662097  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.215s	user 0.151s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":12042,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36463,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":64256,"update_count":2500}
I20260812 06:20:29.662863  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:29.732735  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.069s	user 0.027s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28918,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.733333  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:29.744302  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4363,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.744807  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushMRSOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:29.786401  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushMRSOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.041s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":407,"dirs.run_wall_time_us":1777,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1502,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:29.787207  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling LogGCOp(122b888fbbe34096bb6b0a7948642c02): free 121006382 bytes of WAL
I20260812 06:20:29.787458  5640 log_reader.cc:385] T 122b888fbbe34096bb6b0a7948642c02: removed 12 log segments from log reader
I20260812 06:20:29.787529  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000003 (ops 11-15)
I20260812 06:20:29.787580  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000004 (ops 16-20)
I20260812 06:20:29.787638  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000005 (ops 21-25)
I20260812 06:20:29.787678  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000006 (ops 26-30)
I20260812 06:20:29.787703  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000007 (ops 31-35)
I20260812 06:20:29.787725  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000008 (ops 36-40)
I20260812 06:20:29.787748  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000009 (ops 41-45)
I20260812 06:20:29.787776  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000010 (ops 46-50)
I20260812 06:20:29.787820  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000011 (ops 51-55)
I20260812 06:20:29.787860  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000012 (ops 56-60)
I20260812 06:20:29.787900  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000013 (ops 61-64)
I20260812 06:20:29.787938  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000014 (ops 65-69)
I20260812 06:20:29.813488  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: LogGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:29.813912  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:29.836475  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.836921  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:29.847129  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.847576  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:30.077199  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.229s	user 0.161s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3345,"lbm_read_time_us":16192,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38213,"lbm_writes_lt_1ms":743,"mutex_wait_us":1235,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:20:30.078063  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02): 462 bytes on disk
I20260812 06:20:30.078689  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:20:30.079602  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:30.138870  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.059s	user 0.031s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.139449  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:30.166457  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.027s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.166992  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:30.179103  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.179569  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:30.397353  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.218s	user 0.145s	sys 0.072s 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":735,"lbm_read_time_us":15462,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37308,"lbm_writes_lt_1ms":643,"mutex_wait_us":335,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":703744,"update_count":3000}
I20260812 06:20:30.398129  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:30.458881  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.061s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21401,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.459453  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:30.471495  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.472015  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:30.639919  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.168s	user 0.127s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":12137,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28410,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2500}
I20260812 06:20:30.640451  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:30.694911  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.054s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21239,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.695459  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:30.712328  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6560,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.712829  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:30.880307  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.167s	user 0.097s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1193,"lbm_read_time_us":11679,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26160,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:20:30.880815  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:30.943260  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.062s	user 0.018s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18792,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.943768  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:30.956920  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.957463  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:31.159526  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.202s	user 0.143s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":13633,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34432,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:20:31.160162  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=11.118625
I20260812 06:20:31.195430  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15039,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:31.197387  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:31.212167  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5711,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.212874  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:31.395239  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.182s	user 0.119s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":10777,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27058,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:20:31.396104  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:31.450196  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.054s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22717,"lbm_writes_lt_1ms":403,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.450752  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:31.463267  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.463776  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushMRSOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:31.499285  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushMRSOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1427,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1763,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:31.500511  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling LogGCOp(122b888fbbe34096bb6b0a7948642c02): free 132571381 bytes of WAL
I20260812 06:20:31.500828  5640 log_reader.cc:385] T 122b888fbbe34096bb6b0a7948642c02: removed 13 log segments from log reader
I20260812 06:20:31.500936  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000015 (ops 70-74)
I20260812 06:20:31.500999  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000016 (ops 75-79)
I20260812 06:20:31.501051  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000017 (ops 80-84)
I20260812 06:20:31.501094  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000018 (ops 85-89)
I20260812 06:20:31.501121  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000019 (ops 90-94)
I20260812 06:20:31.501168  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000020 (ops 95-98)
I20260812 06:20:31.501241  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000021 (ops 99-103)
I20260812 06:20:31.501299  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000022 (ops 104-108)
I20260812 06:20:31.501359  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000023 (ops 109-113)
I20260812 06:20:31.501406  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000024 (ops 114-118)
I20260812 06:20:31.501448  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000025 (ops 119-123)
I20260812 06:20:31.501493  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000026 (ops 124-128)
I20260812 06:20:31.501539  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000027 (ops 129-132)
I20260812 06:20:31.529821  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: LogGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:31.530229  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=6.157687
I20260812 06:20:31.550140  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.020s	user 0.009s	sys 0.009s Metrics: {"bytes_written":7671762,"delete_count":0,"lbm_write_time_us":7838,"lbm_writes_lt_1ms":190,"reinsert_count":0,"update_count":935}
I20260812 06:20:31.551223  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02): 493 bytes on disk
I20260812 06:20:31.551873  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.552472  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:31.796873  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.244s	user 0.164s	sys 0.078s Metrics: {"cfile_cache_miss":720,"cfile_cache_miss_bytes":32446317,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":312,"lbm_read_time_us":17685,"lbm_reads_lt_1ms":756,"lbm_write_time_us":42289,"lbm_writes_lt_1ms":730,"mutex_wait_us":65,"peak_mem_usage":86395205,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":112,"threads_started":1,"update_count":3435}
I20260812 06:20:31.797657  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=15.087375
I20260812 06:20:31.859093  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.061s	user 0.027s	sys 0.030s Metrics: {"bytes_written":17353465,"delete_count":0,"lbm_write_time_us":20674,"lbm_writes_lt_1ms":426,"reinsert_count":0,"update_count":2115}
I20260812 06:20:31.859781  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:31.881218  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.021s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.881680  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:32.057933  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.176s	user 0.112s	sys 0.064s Metrics: {"cfile_cache_miss":545,"cfile_cache_miss_bytes":25307998,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1288,"lbm_read_time_us":11368,"lbm_reads_lt_1ms":577,"lbm_write_time_us":29712,"lbm_writes_lt_1ms":556,"mutex_wait_us":351,"peak_mem_usage":64689739,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2565}
I20260812 06:20:32.058549  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:32.110090  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.051s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17673,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.110714  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:32.126994  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.127641  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:32.304682  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.177s	user 0.101s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":933,"lbm_read_time_us":12272,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28248,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31488,"update_count":2500}
I20260812 06:20:32.305365  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:32.358816  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.053s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19409,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.359264  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:32.371325  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.371953  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:32.557206  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.185s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":9258,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31489,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:20:32.557826  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:32.608690  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.051s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19032,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.609265  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:32.620699  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.621315  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:32.779876  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.158s	user 0.133s	sys 0.017s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":940,"lbm_read_time_us":10354,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28882,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:32.780558  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:32.835716  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.055s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24673,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.836261  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:32.847738  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.848524  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:33.009848  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.161s	user 0.113s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":9762,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32831,"lbm_writes_lt_1ms":543,"mutex_wait_us":87,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:33.010535  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=14.095187
I20260812 06:20:33.062536  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.052s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25444,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.063102  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=2.188937
I20260812 06:20:33.075394  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.075887  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushMRSOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:33.109505  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushMRSOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.033s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1521,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1840,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:33.110176  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling LogGCOp(122b888fbbe34096bb6b0a7948642c02): free 133024654 bytes of WAL
I20260812 06:20:33.110411  5640 log_reader.cc:385] T 122b888fbbe34096bb6b0a7948642c02: removed 13 log segments from log reader
I20260812 06:20:33.110476  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000028 (ops 133-137)
I20260812 06:20:33.110530  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000029 (ops 138-142)
I20260812 06:20:33.110589  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000030 (ops 143-147)
I20260812 06:20:33.110630  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000031 (ops 148-152)
I20260812 06:20:33.110666  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000032 (ops 153-156)
I20260812 06:20:33.110704  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000033 (ops 157-161)
I20260812 06:20:33.110741  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000034 (ops 162-166)
I20260812 06:20:33.110777  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000035 (ops 167-171)
I20260812 06:20:33.110814  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000036 (ops 172-176)
I20260812 06:20:33.110862  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000037 (ops 177-181)
I20260812 06:20:33.110906  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000038 (ops 182-186)
I20260812 06:20:33.110942  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000039 (ops 187-191)
I20260812 06:20:33.110980  5640 log.cc:1079] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: Deleting log segment in path: /tmp/dist-test-task6f_rMt/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622463918-5301-0/minicluster-data/ts-0-root/wals/122b888fbbe34096bb6b0a7948642c02/wal-000000040 (ops 192-196)
I20260812 06:20:33.145171  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: LogGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:33.145807  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=4.173312
I20260812 06:20:33.166553  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.021s	user 0.011s	sys 0.009s Metrics: {"bytes_written":5907729,"delete_count":0,"lbm_write_time_us":8197,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:20:33.167124  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.196750
I20260812 06:20:33.178439  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: FlushDeltaMemStoresOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":3580,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:20:33.179026  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02): 493 bytes on disk
I20260812 06:20:33.179662  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: UndoDeltaBlockGCOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:20:33.180928  5708 maintenance_manager.cc:419] P 5aaaae89940043e6b38e8675b3c69054: Scheduling MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02): perf score=1.000000
I20260812 06:20:33.220254  5301 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.069s	user 1.881s	sys 0.163s
I20260812 06:20:33.329054  5301 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.001s	sys 0.000s
I20260812 06:20:33.329734  5301 tablet_server.cc:179] TabletServer@127.5.45.65:0 shutting down...
I20260812 06:20:33.395318  5640 maintenance_manager.cc:643] P 5aaaae89940043e6b38e8675b3c69054: MajorDeltaCompactionOp(122b888fbbe34096bb6b0a7948642c02) complete. Timing: real 0.214s	user 0.140s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979712,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":811,"lbm_read_time_us":16023,"lbm_reads_lt_1ms":770,"lbm_write_time_us":34686,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:20:33.395936  5301 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:33.396360  5301 tablet_replica.cc:333] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054: stopping tablet replica
I20260812 06:20:33.396574  5301 raft_consensus.cc:2243] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.396760  5301 raft_consensus.cc:2272] T 122b888fbbe34096bb6b0a7948642c02 P 5aaaae89940043e6b38e8675b3c69054 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.402869  5301 tablet_server.cc:196] TabletServer@127.5.45.65:0 shutdown complete.
I20260812 06:20:33.458499  5301 master.cc:562] Master@127.5.45.126:40831 shutting down...
I20260812 06:20:33.461896  5301 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.462066  5301 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.462117  5301 tablet_replica.cc:333] T 00000000000000000000000000000000 P bb3f63a39272411d9a7a129eeac800e7: stopping tablet replica
I20260812 06:20:33.474725  5301 master.cc:584] Master@127.5.45.126:40831 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5644 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11084 ms total)

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