[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:40.853863  1472 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.112.62:40223
I20260812 06:16:40.855113  1472 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:40.855904  1472 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.865480  1482 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.865633  1472 server_base.cc:1061] running on GCE node
W20260812 06:16:40.865831  1479 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.865520  1480 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.866647  1472 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.866806  1472 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:40.866869  1472 hybrid_clock.cc:648] HybridClock initialized: now 1786515400866866 us; error 0 us; skew 500 ppm
I20260812 06:16:40.869055  1472 webserver.cc:533] Webserver started at http://127.1.112.62:39765/ using document root <none> and password file <none>
I20260812 06:16:40.869808  1472 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.869911  1472 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.870185  1472 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.872641  1472 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/master-0-root/instance:
uuid: "4e689dfaac7f4d5fb9889cd04533279c"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-g350"
I20260812 06:16:40.877156  1472 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:16:40.880125  1487 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.881446  1472 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:40.881654  1472 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/master-0-root
uuid: "4e689dfaac7f4d5fb9889cd04533279c"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-g350"
I20260812 06:16:40.881925  1472 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:40.908033  1472 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.908864  1472 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:40.909083  1472 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.919389  1472 rpc_server.cc:307] RPC server started. Bound to: 127.1.112.62:40223
I20260812 06:16:40.919409  1543 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.112.62:40223 every 8 connection(s)
I20260812 06:16:40.922353  1544 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.928820  1544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: Bootstrap starting.
I20260812 06:16:40.931595  1544 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.932694  1544 log.cc:826] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:40.936013  1544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: No bootstrap required, opened a new log
I20260812 06:16:40.939674  1544 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER }
I20260812 06:16:40.939932  1544 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.940028  1544 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4e689dfaac7f4d5fb9889cd04533279c, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.940785  1544 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [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: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER }
I20260812 06:16:40.940966  1544 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.941020  1544 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.941176  1544 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.942327  1544 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER }
I20260812 06:16:40.942893  1544 leader_election.cc:304] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [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: 4e689dfaac7f4d5fb9889cd04533279c; no voters: 
I20260812 06:16:40.943315  1544 leader_election.cc:290] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.943540  1547 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.943935  1547 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 1 LEADER]: Becoming Leader. State: Replica: 4e689dfaac7f4d5fb9889cd04533279c, State: Running, Role: LEADER
I20260812 06:16:40.944485  1547 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [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: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER }
I20260812 06:16:40.944828  1544 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.946970  1548 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4e689dfaac7f4d5fb9889cd04533279c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER } }
I20260812 06:16:40.947160  1548 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.947432  1549 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4e689dfaac7f4d5fb9889cd04533279c. Latest consensus state: current_term: 1 leader_uuid: "4e689dfaac7f4d5fb9889cd04533279c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e689dfaac7f4d5fb9889cd04533279c" member_type: VOTER } }
I20260812 06:16:40.947520  1567 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.947528  1549 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.947520  1472 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:40.950229  1567 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.956064  1567 catalog_manager.cc:1383] Generated new cluster ID: 2ee4414b1cfa4a6fb4ea60949662b2f9
I20260812 06:16:40.956166  1567 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.967289  1567 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.968606  1567 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.982657  1567 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: Generated new TSK 0
I20260812 06:16:40.983695  1567 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:41.013032  1472 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:41.017335  1575 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:41.017441  1572 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:41.017654  1472 server_base.cc:1061] running on GCE node
W20260812 06:16:41.017416  1573 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:41.018010  1472 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:41.018100  1472 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:41.018142  1472 hybrid_clock.cc:648] HybridClock initialized: now 1786515401018140 us; error 0 us; skew 500 ppm
I20260812 06:16:41.019819  1472 webserver.cc:533] Webserver started at http://127.1.112.1:32787/ using document root <none> and password file <none>
I20260812 06:16:41.020040  1472 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:41.020119  1472 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:41.020226  1472 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:41.020679  1472 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/instance:
uuid: "d2b52c1c2bad4bb78d6b4e60148ed271"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-g350"
I20260812 06:16:41.022539  1472 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:41.023762  1583 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.024302  1472 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:41.024461  1472 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root
uuid: "d2b52c1c2bad4bb78d6b4e60148ed271"
format_stamp: "Formatted at 2026-08-12 06:16:41 on dist-test-slave-g350"
I20260812 06:16:41.024565  1472 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:41.034811  1472 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:41.035450  1472 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:41.036116  1472 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:41.037063  1472 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:41.037118  1472 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.037197  1472 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:41.037238  1472 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:41.044772  1472 rpc_server.cc:307] RPC server started. Bound to: 127.1.112.1:35045
I20260812 06:16:41.044804  1659 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.112.1:35045 every 8 connection(s)
I20260812 06:16:41.058149  1660 heartbeater.cc:344] Connected to a master server at 127.1.112.62:40223
I20260812 06:16:41.058490  1660 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:41.059122  1660 heartbeater.cc:507] Master 127.1.112.62:40223 requested a full tablet report, sending...
I20260812 06:16:41.060791  1505 ts_manager.cc:194] Registered new tserver with Master: d2b52c1c2bad4bb78d6b4e60148ed271 (127.1.112.1:35045)
I20260812 06:16:41.061640  1472 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016034369s
I20260812 06:16:41.062373  1505 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58144
I20260812 06:16:41.074558  1505 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58146:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:41.094096  1607 tablet_service.cc:1511] Processing CreateTablet for tablet eeccad6613e44379b5009aa17810e1aa (DEFAULT_TABLE table=heavy-update-compaction-test [id=2013d938ed1d42f4907b240f45dbaab0]), partition=
I20260812 06:16:41.094900  1607 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet eeccad6613e44379b5009aa17810e1aa. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:41.098482  1674 tablet_bootstrap.cc:492] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Bootstrap starting.
I20260812 06:16:41.099545  1674 tablet_bootstrap.cc:654] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:41.100883  1674 tablet_bootstrap.cc:492] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: No bootstrap required, opened a new log
I20260812 06:16:41.100992  1674 ts_tablet_manager.cc:1403] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:41.102078  1674 raft_consensus.cc:359] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b52c1c2bad4bb78d6b4e60148ed271" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 35045 } }
I20260812 06:16:41.102322  1674 raft_consensus.cc:385] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:41.102370  1674 raft_consensus.cc:740] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2b52c1c2bad4bb78d6b4e60148ed271, State: Initialized, Role: FOLLOWER
I20260812 06:16:41.102627  1674 consensus_queue.cc:260] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [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: "d2b52c1c2bad4bb78d6b4e60148ed271" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 35045 } }
I20260812 06:16:41.102774  1674 raft_consensus.cc:399] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:41.102824  1674 raft_consensus.cc:493] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:41.102929  1674 raft_consensus.cc:3060] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:41.104064  1674 raft_consensus.cc:515] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b52c1c2bad4bb78d6b4e60148ed271" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 35045 } }
I20260812 06:16:41.104277  1674 leader_election.cc:304] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [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: d2b52c1c2bad4bb78d6b4e60148ed271; no voters: 
I20260812 06:16:41.104614  1674 leader_election.cc:290] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:41.104933  1677 raft_consensus.cc:2804] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:41.105266  1674 ts_tablet_manager.cc:1434] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:41.105348  1677 raft_consensus.cc:697] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 1 LEADER]: Becoming Leader. State: Replica: d2b52c1c2bad4bb78d6b4e60148ed271, State: Running, Role: LEADER
I20260812 06:16:41.105554  1660 heartbeater.cc:499] Master 127.1.112.62:40223 was elected leader, sending a full tablet report...
I20260812 06:16:41.105638  1677 consensus_queue.cc:237] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [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: "d2b52c1c2bad4bb78d6b4e60148ed271" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 35045 } }
I20260812 06:16:41.109026  1503 catalog_manager.cc:5719] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 reported cstate change: term changed from 0 to 1, leader changed from <none> to d2b52c1c2bad4bb78d6b4e60148ed271 (127.1.112.1). New cstate: current_term: 1 leader_uuid: "d2b52c1c2bad4bb78d6b4e60148ed271" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2b52c1c2bad4bb78d6b4e60148ed271" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 35045 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:41.187280  1472 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.071s	user 0.034s	sys 0.001s
I20260812 06:16:41.296901  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushMRSOp(eeccad6613e44379b5009aa17810e1aa): perf score=10.125253
I20260812 06:16:41.461789  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushMRSOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.164s	user 0.119s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":279,"delete_count":0,"dirs.queue_time_us":178,"dirs.run_cpu_time_us":446,"dirs.run_wall_time_us":1221,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38968,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":182,"threads_started":1,"update_count":1500}
I20260812 06:16:41.463385  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling LogGCOp(eeccad6613e44379b5009aa17810e1aa): free 11976772 bytes of WAL
I20260812 06:16:41.463873  1588 log_reader.cc:385] T eeccad6613e44379b5009aa17810e1aa: removed 1 log segments from log reader
I20260812 06:16:41.464006  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000001 (ops 1-6)
I20260812 06:16:41.467653  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: LogGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:41.468153  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:41.497785  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.029s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.498361  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:41.512964  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.513562  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.000000
I20260812 06:16:41.692560  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.179s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692878,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1661,"lbm_read_time_us":11982,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33041,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":369,"threads_started":5,"update_count":2500}
I20260812 06:16:41.693507  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=11.118625
I20260812 06:16:41.734732  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.041s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17686,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.735458  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:41.756837  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.021s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.757355  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa): 8206539 bytes on disk
I20260812 06:16:41.757915  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.758378  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:41.769225  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.769881  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.000000
I20260812 06:16:41.952328  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.182s	user 0.130s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":102,"lbm_read_time_us":10600,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32765,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:41.952955  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=14.095187
I20260812 06:16:42.039546  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.086s	user 0.044s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.040495  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=3.181125
I20260812 06:16:42.146740  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.106s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8336,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:42.147405  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.248554  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.101s	user 0.032s	sys 0.000s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":13663,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:42.249408  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.354504  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.105s	user 0.020s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13352,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.355485  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=7.149875
I20260812 06:16:42.453794  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.098s	user 0.011s	sys 0.016s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":11420,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:42.454457  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.553238  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.099s	user 0.019s	sys 0.013s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":13894,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:42.553982  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.651774  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.098s	user 0.020s	sys 0.013s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":13661,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.652529  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.756278  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.104s	user 0.012s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10653,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.757156  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.859711  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.102s	user 0.025s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12968,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.860555  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:42.967008  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.106s	user 0.019s	sys 0.014s Metrics: {"bytes_written":7425618,"delete_count":0,"lbm_write_time_us":11368,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":183,"reinsert_count":0,"update_count":905}
I20260812 06:16:42.968472  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:43.067317  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.098s	user 0.020s	sys 0.011s Metrics: {"bytes_written":7835859,"delete_count":0,"lbm_write_time_us":14119,"lbm_writes_lt_1ms":194,"reinsert_count":0,"update_count":955}
I20260812 06:16:43.067920  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=4.173312
I20260812 06:16:43.161185  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.093s	user 0.021s	sys 0.002s Metrics: {"bytes_written":5251345,"delete_count":0,"lbm_write_time_us":9118,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:16:43.161940  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:43.213549  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.051s	user 0.016s	sys 0.017s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":14717,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.214133  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:43.292774  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.078s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.293371  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:43.394850  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.101s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.395612  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=7.149875
I20260812 06:16:43.500594  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.105s	user 0.015s	sys 0.012s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":12324,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.501405  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=10.126437
I20260812 06:16:43.600111  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.099s	user 0.024s	sys 0.012s Metrics: {"bytes_written":11692129,"delete_count":0,"lbm_write_time_us":16950,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":287,"reinsert_count":0,"update_count":1425}
I20260812 06:16:43.600791  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=3.181125
I20260812 06:16:43.699294  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.098s	user 0.012s	sys 0.007s Metrics: {"bytes_written":4882129,"delete_count":0,"lbm_write_time_us":7921,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:16:43.700320  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=7.149875
I20260812 06:16:43.802141  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.102s	user 0.020s	sys 0.008s Metrics: {"bytes_written":8902497,"delete_count":0,"lbm_write_time_us":11253,"lbm_writes_lt_1ms":220,"reinsert_count":0,"update_count":1085}
I20260812 06:16:43.802837  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:43.901531  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.098s	user 0.012s	sys 0.012s Metrics: {"bytes_written":8287133,"delete_count":0,"lbm_write_time_us":11155,"lbm_writes_lt_1ms":205,"reinsert_count":0,"update_count":1010}
I20260812 06:16:43.902532  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=7.149875
I20260812 06:16:43.999579  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.097s	user 0.019s	sys 0.004s Metrics: {"bytes_written":8615326,"delete_count":0,"lbm_write_time_us":9130,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:44.000963  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=5.165500
I20260812 06:16:44.102083  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.101s	user 0.024s	sys 0.000s Metrics: {"bytes_written":7302556,"delete_count":0,"lbm_write_time_us":8671,"lbm_writes_lt_1ms":181,"reinsert_count":0,"update_count":890}
I20260812 06:16:44.103127  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:44.195345  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.092s	user 0.005s	sys 0.014s Metrics: {"bytes_written":7753817,"delete_count":0,"lbm_write_time_us":8601,"lbm_writes_lt_1ms":192,"reinsert_count":0,"update_count":945}
I20260812 06:16:44.196075  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:44.226660  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.030s	user 0.018s	sys 0.005s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9777,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:44.227378  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:44.240335  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.241474  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushMRSOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.195565
I20260812 06:16:44.288793  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushMRSOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.047s	user 0.040s	sys 0.005s Metrics: {"bytes_written":2341002,"cfile_init":1,"dirs.queue_time_us":267,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1661,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3601,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":57,"thread_start_us":95,"threads_started":1}
I20260812 06:16:44.289935  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling LogGCOp(eeccad6613e44379b5009aa17810e1aa): free 233698860 bytes of WAL
I20260812 06:16:44.290426  1588 log_reader.cc:385] T eeccad6613e44379b5009aa17810e1aa: removed 23 log segments from log reader
I20260812 06:16:44.290546  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000002 (ops 7-11)
I20260812 06:16:44.290644  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000003 (ops 12-16)
I20260812 06:16:44.290725  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000004 (ops 17-21)
I20260812 06:16:44.290791  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000005 (ops 22-26)
I20260812 06:16:44.290860  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000006 (ops 27-31)
I20260812 06:16:44.290933  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000007 (ops 32-36)
I20260812 06:16:44.291004  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000008 (ops 37-41)
I20260812 06:16:44.291069  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000009 (ops 42-46)
I20260812 06:16:44.291142  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000010 (ops 47-51)
I20260812 06:16:44.291208  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000011 (ops 52-56)
I20260812 06:16:44.291307  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000012 (ops 57-61)
I20260812 06:16:44.291395  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000013 (ops 62-66)
I20260812 06:16:44.291472  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000014 (ops 67-71)
I20260812 06:16:44.291529  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000015 (ops 72-76)
I20260812 06:16:44.291558  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000016 (ops 77-81)
I20260812 06:16:44.291599  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000017 (ops 82-86)
I20260812 06:16:44.291630  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000018 (ops 87-90)
I20260812 06:16:44.291654  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000019 (ops 91-95)
I20260812 06:16:44.291720  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000020 (ops 96-100)
I20260812 06:16:44.291767  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000021 (ops 101-105)
I20260812 06:16:44.291838  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000022 (ops 106-110)
I20260812 06:16:44.291911  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000023 (ops 111-115)
I20260812 06:16:44.291960  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000024 (ops 116-120)
I20260812 06:16:44.342468  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: LogGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.052s	user 0.000s	sys 0.051s Metrics: {}
I20260812 06:16:44.343144  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa): 778 bytes on disk
I20260812 06:16:44.343745  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.344321  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=6.157687
I20260812 06:16:44.382102  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.038s	user 0.011s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11853,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.382700  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:44.395269  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.395960  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.000000
I20260812 06:16:45.913275  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 1.517s	user 0.992s	sys 0.524s Metrics: {"cfile_cache_miss":5057,"cfile_cache_miss_bytes":209304352,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":27,"delta_iterators_relevant":27,"dirs.queue_time_us":1157,"lbm_read_time_us":92526,"lbm_reads_lt_1ms":5097,"lbm_write_time_us":288116,"lbm_writes_lt_1ms":5047,"peak_mem_usage":622311640,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":537,"threads_started":7,"update_count":25000}
I20260812 06:16:45.914232  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=85.532687
I20260812 06:16:46.270293  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.356s	user 0.191s	sys 0.108s Metrics: {"bytes_written":90253450,"delete_count":0,"lbm_write_time_us":149776,"lbm_writes_lt_1ms":2205,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":11000}
I20260812 06:16:46.270905  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=17.071750
I20260812 06:16:46.474196  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.203s	user 0.042s	sys 0.028s Metrics: {"bytes_written":19363641,"delete_count":0,"lbm_write_time_us":34165,"lbm_writes_lt_1ms":475,"reinsert_count":0,"update_count":2360}
I20260812 06:16:46.475317  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=12.110812
I20260812 06:16:46.668498  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.193s	user 0.025s	sys 0.024s Metrics: {"bytes_written":13456171,"delete_count":0,"lbm_write_time_us":23893,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1640}
I20260812 06:16:46.669181  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=14.095187
I20260812 06:16:46.726255  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.057s	user 0.020s	sys 0.033s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":25085,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.726920  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushMRSOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.000000
I20260812 06:16:46.794595  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushMRSOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.067s	user 0.041s	sys 0.001s Metrics: {"bytes_written":1562447,"cfile_init":1,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":343,"dirs.run_wall_time_us":4281,"drs_written":1,"lbm_read_time_us":197,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2597,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":38}
I20260812 06:16:46.795465  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling LogGCOp(eeccad6613e44379b5009aa17810e1aa): free 153356596 bytes of WAL
I20260812 06:16:46.795753  1588 log_reader.cc:385] T eeccad6613e44379b5009aa17810e1aa: removed 15 log segments from log reader
I20260812 06:16:46.795800  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000025 (ops 121-124)
I20260812 06:16:46.795835  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000026 (ops 125-129)
I20260812 06:16:46.795852  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000027 (ops 130-134)
I20260812 06:16:46.795889  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000028 (ops 135-139)
I20260812 06:16:46.795907  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000029 (ops 140-144)
I20260812 06:16:46.795923  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000030 (ops 145-149)
I20260812 06:16:46.795941  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000031 (ops 150-154)
I20260812 06:16:46.795958  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000032 (ops 155-159)
I20260812 06:16:46.796020  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000033 (ops 160-164)
I20260812 06:16:46.796067  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000034 (ops 165-168)
I20260812 06:16:46.796134  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000035 (ops 169-173)
I20260812 06:16:46.796180  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000036 (ops 174-178)
I20260812 06:16:46.796224  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000037 (ops 179-183)
I20260812 06:16:46.796274  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000038 (ops 184-188)
I20260812 06:16:46.796294  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000039 (ops 189-193)
I20260812 06:16:46.832973  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: LogGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.037s	user 0.001s	sys 0.033s Metrics: {}
I20260812 06:16:46.833688  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa): 564 bytes on disk
I20260812 06:16:46.834352  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: UndoDeltaBlockGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.835043  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=7.149875
I20260812 06:16:46.873500  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.038s	user 0.024s	sys 0.010s Metrics: {"bytes_written":9107612,"delete_count":0,"lbm_write_time_us":14296,"lbm_writes_lt_1ms":225,"reinsert_count":0,"update_count":1110}
I20260812 06:16:46.874341  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling LogGCOp(eeccad6613e44379b5009aa17810e1aa): free 12018006 bytes of WAL
I20260812 06:16:46.874614  1588 log_reader.cc:385] T eeccad6613e44379b5009aa17810e1aa: removed 1 log segments from log reader
I20260812 06:16:46.874663  1588 log.cc:1079] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/eeccad6613e44379b5009aa17810e1aa/wal-000000040 (ops 194-198)
I20260812 06:16:46.877141  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: LogGCOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:46.877564  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa): perf score=2.188937
I20260812 06:16:46.888415  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: FlushDeltaMemStoresOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:16:46.889065  1662 maintenance_manager.cc:419] P d2b52c1c2bad4bb78d6b4e60148ed271: Scheduling MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa): perf score=1.000000
I20260812 06:16:46.934291  1472 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.747s	user 2.026s	sys 0.153s
I20260812 06:16:47.384953  1472 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.450s	user 0.002s	sys 0.000s
I20260812 06:16:47.386145  1472 tablet_server.cc:179] TabletServer@127.1.112.1:0 shutting down...
I20260812 06:16:47.965638  1588 maintenance_manager.cc:643] P d2b52c1c2bad4bb78d6b4e60148ed271: MajorDeltaCompactionOp(eeccad6613e44379b5009aa17810e1aa) complete. Timing: real 1.076s	user 0.644s	sys 0.431s Metrics: {"cfile_cache_miss":3738,"cfile_cache_miss_bytes":155970549,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":6,"delta_iterators_relevant":6,"dirs.queue_time_us":2654,"lbm_read_time_us":70312,"lbm_reads_lt_1ms":3774,"lbm_write_time_us":168983,"lbm_writes_lt_1ms":3746,"mutex_wait_us":70,"peak_mem_usage":460766204,"reinsert_count":0,"spinlock_wait_cycles":1627392,"thread_start_us":654,"threads_started":7,"update_count":18500}
I20260812 06:16:47.966835  1472 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.967623  1472 tablet_replica.cc:333] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271: stopping tablet replica
I20260812 06:16:47.967950  1472 raft_consensus.cc:2243] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.968638  1472 raft_consensus.cc:2272] T eeccad6613e44379b5009aa17810e1aa P d2b52c1c2bad4bb78d6b4e60148ed271 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.986445  1472 tablet_server.cc:196] TabletServer@127.1.112.1:0 shutdown complete.
I20260812 06:16:48.531025  1472 master.cc:562] Master@127.1.112.62:40223 shutting down...
I20260812 06:16:48.535568  1472 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.535805  1472 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.535929  1472 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4e689dfaac7f4d5fb9889cd04533279c: stopping tablet replica
I20260812 06:16:48.549046  1472 master.cc:584] Master@127.1.112.62:40223 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (7802 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:48.686283  1472 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.112.62:40749
I20260812 06:16:48.686878  1472 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:48.690279  1714 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.690311  1472 server_base.cc:1061] running on GCE node
W20260812 06:16:48.690389  1711 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:48.690583  1712 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.690819  1472 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:48.690894  1472 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:48.690922  1472 hybrid_clock.cc:648] HybridClock initialized: now 1786515408690921 us; error 0 us; skew 500 ppm
I20260812 06:16:48.691826  1472 webserver.cc:533] Webserver started at http://127.1.112.62:39157/ using document root <none> and password file <none>
I20260812 06:16:48.692030  1472 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:48.692112  1472 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:48.692227  1472 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:48.692656  1472 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/master-0-root/instance:
uuid: "8c190530110f4aafa26e96b28752d83c"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-g350"
I20260812 06:16:48.694540  1472 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:48.695761  1721 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.696131  1472 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:48.696236  1472 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/master-0-root
uuid: "8c190530110f4aafa26e96b28752d83c"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-g350"
I20260812 06:16:48.696349  1472 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:48.706682  1472 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:48.707156  1472 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:48.713008  1472 rpc_server.cc:307] RPC server started. Bound to: 127.1.112.62:40749
I20260812 06:16:48.730984  1783 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.112.62:40749 every 8 connection(s)
I20260812 06:16:48.731493  1784 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:48.733466  1784 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c: Bootstrap starting.
I20260812 06:16:48.734368  1784 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:48.735594  1784 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c: No bootstrap required, opened a new log
I20260812 06:16:48.736033  1784 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER }
I20260812 06:16:48.736137  1784 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:48.736162  1784 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c190530110f4aafa26e96b28752d83c, State: Initialized, Role: FOLLOWER
I20260812 06:16:48.736338  1784 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [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: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER }
I20260812 06:16:48.736438  1784 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:48.736464  1784 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:48.736493  1784 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:48.737260  1784 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER }
I20260812 06:16:48.737396  1784 leader_election.cc:304] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [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: 8c190530110f4aafa26e96b28752d83c; no voters: 
I20260812 06:16:48.737625  1784 leader_election.cc:290] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:48.737833  1788 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:48.738030  1788 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 1 LEADER]: Becoming Leader. State: Replica: 8c190530110f4aafa26e96b28752d83c, State: Running, Role: LEADER
I20260812 06:16:48.738234  1788 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [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: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER }
I20260812 06:16:48.738238  1784 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:48.738758  1790 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8c190530110f4aafa26e96b28752d83c. Latest consensus state: current_term: 1 leader_uuid: "8c190530110f4aafa26e96b28752d83c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER } }
I20260812 06:16:48.738852  1790 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:48.738739  1789 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8c190530110f4aafa26e96b28752d83c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c190530110f4aafa26e96b28752d83c" member_type: VOTER } }
I20260812 06:16:48.738987  1789 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:48.739250  1792 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:48.740413  1792 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:48.740769  1472 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:48.743955  1792 catalog_manager.cc:1383] Generated new cluster ID: 473b983a2ab249e2a9f3754a61b19251
I20260812 06:16:48.744328  1792 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:48.756940  1792 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:48.757735  1792 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:48.769937  1792 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c: Generated new TSK 0
I20260812 06:16:48.770210  1792 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:48.773952  1472 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:48.777690  1810 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.777742  1472 server_base.cc:1061] running on GCE node
W20260812 06:16:48.777809  1811 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:48.777778  1814 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.778375  1472 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:48.778434  1472 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:48.778455  1472 hybrid_clock.cc:648] HybridClock initialized: now 1786515408778455 us; error 0 us; skew 500 ppm
I20260812 06:16:48.779726  1472 webserver.cc:533] Webserver started at http://127.1.112.1:37253/ using document root <none> and password file <none>
I20260812 06:16:48.779929  1472 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:48.779986  1472 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:48.780048  1472 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:48.780517  1472 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/instance:
uuid: "051429b4a1054a4fa12142f23505a586"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-g350"
I20260812 06:16:48.782662  1472 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:48.783981  1820 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.784358  1472 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:48.784473  1472 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root
uuid: "051429b4a1054a4fa12142f23505a586"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-g350"
I20260812 06:16:48.784588  1472 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:48.794715  1472 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:48.795238  1472 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:48.795651  1472 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:48.796212  1472 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:48.796278  1472 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.796353  1472 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:48.796397  1472 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.801580  1472 rpc_server.cc:307] RPC server started. Bound to: 127.1.112.1:40143
I20260812 06:16:48.801788  1893 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.112.1:40143 every 8 connection(s)
I20260812 06:16:48.809401  1894 heartbeater.cc:344] Connected to a master server at 127.1.112.62:40749
I20260812 06:16:48.809808  1894 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:48.810272  1894 heartbeater.cc:507] Master 127.1.112.62:40749 requested a full tablet report, sending...
I20260812 06:16:48.811493  1742 ts_manager.cc:194] Registered new tserver with Master: 051429b4a1054a4fa12142f23505a586 (127.1.112.1:40143)
I20260812 06:16:48.811560  1472 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009347351s
I20260812 06:16:48.812583  1742 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57000
I20260812 06:16:48.822140  1742 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57014:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:48.836266  1852 tablet_service.cc:1511] Processing CreateTablet for tablet fce7ab8961744d40beaa3927e026ac9d (DEFAULT_TABLE table=heavy-update-compaction-test [id=99b583f4552844fc9309b8352d680187]), partition=
I20260812 06:16:48.836706  1852 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fce7ab8961744d40beaa3927e026ac9d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:48.839560  1908 tablet_bootstrap.cc:492] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Bootstrap starting.
I20260812 06:16:48.840776  1908 tablet_bootstrap.cc:654] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:48.842327  1908 tablet_bootstrap.cc:492] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: No bootstrap required, opened a new log
I20260812 06:16:48.842576  1908 ts_tablet_manager.cc:1403] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:48.843092  1908 raft_consensus.cc:359] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051429b4a1054a4fa12142f23505a586" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 40143 } }
I20260812 06:16:48.843218  1908 raft_consensus.cc:385] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:48.843251  1908 raft_consensus.cc:740] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 051429b4a1054a4fa12142f23505a586, State: Initialized, Role: FOLLOWER
I20260812 06:16:48.843421  1908 consensus_queue.cc:260] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [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: "051429b4a1054a4fa12142f23505a586" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 40143 } }
I20260812 06:16:48.843501  1908 raft_consensus.cc:399] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:48.843525  1908 raft_consensus.cc:493] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:48.843556  1908 raft_consensus.cc:3060] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:48.844523  1908 raft_consensus.cc:515] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051429b4a1054a4fa12142f23505a586" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 40143 } }
I20260812 06:16:48.844702  1908 leader_election.cc:304] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [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: 051429b4a1054a4fa12142f23505a586; no voters: 
I20260812 06:16:48.846131  1908 leader_election.cc:290] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:48.847451  1908 ts_tablet_manager.cc:1434] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Time spent starting tablet: real 0.005s	user 0.000s	sys 0.004s
I20260812 06:16:48.847549  1910 raft_consensus.cc:2804] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:48.847797  1894 heartbeater.cc:499] Master 127.1.112.62:40749 was elected leader, sending a full tablet report...
I20260812 06:16:48.847997  1910 raft_consensus.cc:697] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 1 LEADER]: Becoming Leader. State: Replica: 051429b4a1054a4fa12142f23505a586, State: Running, Role: LEADER
I20260812 06:16:48.848245  1910 consensus_queue.cc:237] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [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: "051429b4a1054a4fa12142f23505a586" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 40143 } }
I20260812 06:16:48.850244  1742 catalog_manager.cc:5719] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 reported cstate change: term changed from 0 to 1, leader changed from <none> to 051429b4a1054a4fa12142f23505a586 (127.1.112.1). New cstate: current_term: 1 leader_uuid: "051429b4a1054a4fa12142f23505a586" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "051429b4a1054a4fa12142f23505a586" member_type: VOTER last_known_addr { host: "127.1.112.1" port: 40143 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:48.925451  1472 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.017s	sys 0.012s
I20260812 06:16:49.052870  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d): perf score=15.086190
I20260812 06:16:49.203482  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.150s	user 0.100s	sys 0.048s Metrics: {"bytes_written":9476827,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":129,"dirs.run_cpu_time_us":411,"dirs.run_wall_time_us":1329,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34073,"lbm_writes_lt_1ms":588,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1155}
I20260812 06:16:49.204511  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling LogGCOp(fce7ab8961744d40beaa3927e026ac9d): free 11976772 bytes of WAL
I20260812 06:16:49.204826  1826 log_reader.cc:385] T fce7ab8961744d40beaa3927e026ac9d: removed 1 log segments from log reader
I20260812 06:16:49.204875  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000001 (ops 1-6)
I20260812 06:16:49.207463  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: LogGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:49.207873  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.196750
I20260812 06:16:49.217917  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:16:49.218452  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d): 12308959 bytes on disk
I20260812 06:16:49.218993  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.219532  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:49.446903  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.227s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528870,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":58,"lbm_read_time_us":9640,"lbm_reads_lt_1ms":368,"lbm_write_time_us":26296,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":439,"threads_started":5,"update_count":1500}
I20260812 06:16:49.448048  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:49.545006  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.097s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24160,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.545749  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=6.157687
I20260812 06:16:49.635572  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.090s	user 0.015s	sys 0.017s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13770,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:49.636353  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=4.173312
I20260812 06:16:49.735210  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.099s	user 0.007s	sys 0.009s Metrics: {"bytes_written":5456467,"delete_count":0,"lbm_write_time_us":6559,"lbm_writes_lt_1ms":136,"reinsert_count":0,"update_count":665}
I20260812 06:16:49.735998  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=9.134250
I20260812 06:16:49.770416  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.034s	user 0.025s	sys 0.008s Metrics: {"bytes_written":10953703,"delete_count":0,"lbm_write_time_us":14493,"lbm_writes_lt_1ms":270,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1335}
I20260812 06:16:49.771026  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:50.193691  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.422s	user 0.273s	sys 0.149s Metrics: {"cfile_cache_miss":1034,"cfile_cache_miss_bytes":45246038,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":921,"lbm_read_time_us":26929,"lbm_reads_lt_1ms":1066,"lbm_write_time_us":80850,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":1041,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":448,"threads_started":6,"update_count":5000}
I20260812 06:16:50.194497  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=22.032687
I20260812 06:16:50.273975  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.079s	user 0.056s	sys 0.020s Metrics: {"bytes_written":24614722,"delete_count":0,"lbm_write_time_us":34402,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:16:50.274627  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:50.297797  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.023s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.298411  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:50.547959  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.249s	user 0.189s	sys 0.056s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32938544,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":18803,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":763,"lbm_write_time_us":49154,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3500}
I20260812 06:16:50.548897  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:50.631536  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.082s	user 0.065s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":34370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.632416  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:50.666355  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.034s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.667155  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:50.688796  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.021s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":8185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.689527  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:50.893949  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.204s	user 0.165s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836254,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1069,"lbm_read_time_us":14417,"lbm_reads_lt_1ms":665,"lbm_write_time_us":39883,"lbm_writes_lt_1ms":643,"mutex_wait_us":325,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":3000}
I20260812 06:16:50.894909  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:50.955438  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.060s	user 0.045s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26853,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.956073  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:50.967427  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.967974  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:51.002441  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1694,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1797,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:51.003234  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling LogGCOp(fce7ab8961744d40beaa3927e026ac9d): free 129320453 bytes of WAL
I20260812 06:16:51.003593  1826 log_reader.cc:385] T fce7ab8961744d40beaa3927e026ac9d: removed 13 log segments from log reader
I20260812 06:16:51.003659  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000002 (ops 7-11)
I20260812 06:16:51.003701  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000003 (ops 12-16)
I20260812 06:16:51.003746  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000004 (ops 17-20)
I20260812 06:16:51.003779  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000005 (ops 21-25)
I20260812 06:16:51.003803  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000006 (ops 26-30)
I20260812 06:16:51.003842  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000007 (ops 31-35)
I20260812 06:16:51.003870  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000008 (ops 36-40)
I20260812 06:16:51.003906  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000009 (ops 41-45)
I20260812 06:16:51.003939  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000010 (ops 46-50)
I20260812 06:16:51.003969  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000011 (ops 51-54)
I20260812 06:16:51.003998  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000012 (ops 55-59)
I20260812 06:16:51.004029  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000013 (ops 60-64)
I20260812 06:16:51.004062  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000014 (ops 65-69)
I20260812 06:16:51.034403  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: LogGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:51.034960  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d): 483 bytes on disk
I20260812 06:16:51.035524  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.036092  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:51.060879  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.025s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.061535  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:51.073247  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.073848  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:51.292014  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.218s	user 0.145s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":399,"lbm_read_time_us":16404,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42200,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21120,"thread_start_us":143,"threads_started":1,"update_count":3500}
I20260812 06:16:51.295990  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:51.350739  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.054s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24775,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.351471  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:51.370441  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.371315  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:51.559460  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.188s	user 0.124s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":12757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34273,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65664,"update_count":2500}
I20260812 06:16:51.560070  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:51.628297  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.068s	user 0.041s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26590,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.628943  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:51.645905  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.646720  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:51.861747  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.215s	user 0.143s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":879,"lbm_read_time_us":14341,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36382,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:16:51.862609  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:51.924355  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.061s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24054,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.924960  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:51.938028  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.938586  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:52.135355  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.197s	user 0.136s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1075,"lbm_read_time_us":13104,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34649,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":44672,"update_count":2500}
I20260812 06:16:52.136281  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:52.199396  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.063s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23477,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.200110  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:52.211443  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.211978  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:52.408278  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.196s	user 0.103s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":722,"lbm_read_time_us":12858,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30054,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:16:52.409262  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:52.480404  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.071s	user 0.046s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26967,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.481120  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:52.494875  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.495388  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:52.689126  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.194s	user 0.137s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3915,"lbm_read_time_us":13308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32922,"lbm_writes_lt_1ms":543,"mutex_wait_us":3248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:16:52.690132  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=11.118625
I20260812 06:16:52.744779  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.054s	user 0.024s	sys 0.023s Metrics: {"bytes_written":13086952,"delete_count":0,"lbm_write_time_us":22358,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":321,"reinsert_count":0,"update_count":1595}
I20260812 06:16:52.745687  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:52.772176  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.026s	user 0.009s	sys 0.012s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:16:52.772851  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:52.783921  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:52.784572  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:52.824443  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.040s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":361,"dirs.run_wall_time_us":1540,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1671,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:52.825193  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d): 492 bytes on disk
I20260812 06:16:52.825668  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.826283  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:53.009750  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.183s	user 0.106s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733826,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1283,"lbm_read_time_us":10320,"lbm_reads_lt_1ms":565,"lbm_write_time_us":32081,"lbm_writes_lt_1ms":543,"mutex_wait_us":398,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:16:53.010711  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling LogGCOp(fce7ab8961744d40beaa3927e026ac9d): free 133024437 bytes of WAL
I20260812 06:16:53.011165  1826 log_reader.cc:385] T fce7ab8961744d40beaa3927e026ac9d: removed 13 log segments from log reader
I20260812 06:16:53.011252  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000015 (ops 70-74)
I20260812 06:16:53.011308  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000016 (ops 75-79)
I20260812 06:16:53.011353  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000017 (ops 80-84)
I20260812 06:16:53.011399  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000018 (ops 85-89)
I20260812 06:16:53.011441  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000019 (ops 90-94)
I20260812 06:16:53.011483  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000020 (ops 95-99)
I20260812 06:16:53.011687  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000021 (ops 100-104)
I20260812 06:16:53.011749  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000022 (ops 105-109)
I20260812 06:16:53.011783  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000023 (ops 110-114)
I20260812 06:16:53.011817  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000024 (ops 115-118)
I20260812 06:16:53.011987  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000025 (ops 119-123)
I20260812 06:16:53.012054  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000026 (ops 124-128)
I20260812 06:16:53.012091  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000027 (ops 129-133)
I20260812 06:16:53.045302  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: LogGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.034s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:16:53.046109  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=18.063937
I20260812 06:16:53.126183  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.080s	user 0.047s	sys 0.032s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31965,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:53.126987  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:53.161121  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.034s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.161895  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:53.176239  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.176867  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:53.443888  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.267s	user 0.186s	sys 0.079s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938668,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":402,"lbm_read_time_us":16850,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42825,"lbm_writes_lt_1ms":743,"mutex_wait_us":96,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":34944,"update_count":3500}
I20260812 06:16:53.444973  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=18.063937
I20260812 06:16:53.526139  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.081s	user 0.065s	sys 0.008s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32671,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:53.526785  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:53.538483  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.539436  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:53.772194  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.232s	user 0.137s	sys 0.094s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3432,"lbm_read_time_us":16211,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39999,"lbm_writes_lt_1ms":643,"mutex_wait_us":874,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":43520,"update_count":3000}
I20260812 06:16:53.773350  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:53.832042  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.058s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24365,"lbm_writes_lt_1ms":403,"mutex_wait_us":103,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.832751  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:53.845479  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.846177  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:54.061559  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.215s	user 0.156s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":468,"lbm_read_time_us":13457,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35758,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:16:54.062422  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:54.129766  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.067s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26912,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.130483  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:54.147468  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.148190  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:54.360965  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.212s	user 0.130s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":675,"lbm_read_time_us":14217,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34903,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2500}
I20260812 06:16:54.361800  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:54.425778  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.064s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21402,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.426422  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:54.437510  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.438098  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:54.469405  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushMRSOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":361,"dirs.run_wall_time_us":1610,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1526,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:54.470350  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d): 447 bytes on disk
I20260812 06:16:54.471084  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: UndoDeltaBlockGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.471766  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:54.667023  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.195s	user 0.134s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1081,"lbm_read_time_us":13971,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32092,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:16:54.667750  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling LogGCOp(fce7ab8961744d40beaa3927e026ac9d): free 115943432 bytes of WAL
I20260812 06:16:54.668035  1826 log_reader.cc:385] T fce7ab8961744d40beaa3927e026ac9d: removed 11 log segments from log reader
I20260812 06:16:54.668110  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000028 (ops 134-138)
I20260812 06:16:54.668218  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000029 (ops 139-143)
I20260812 06:16:54.668290  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000030 (ops 144-148)
I20260812 06:16:54.668366  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000031 (ops 149-153)
I20260812 06:16:54.668408  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000032 (ops 154-158)
I20260812 06:16:54.668480  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000033 (ops 159-163)
I20260812 06:16:54.668521  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000034 (ops 164-168)
I20260812 06:16:54.668593  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000035 (ops 169-173)
I20260812 06:16:54.668634  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000036 (ops 174-178)
I20260812 06:16:54.668694  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000037 (ops 179-183)
I20260812 06:16:54.668735  1826 log.cc:1079] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: Deleting log segment in path: /tmp/dist-test-taskkXHSL2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400840813-1472-0/minicluster-data/ts-0-root/wals/fce7ab8961744d40beaa3927e026ac9d/wal-000000038 (ops 184-188)
I20260812 06:16:54.695397  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: LogGCOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:54.696007  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=14.095187
I20260812 06:16:54.756258  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.060s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22565,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.757177  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:54.783339  1472 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.858s	user 2.115s	sys 0.170s
I20260812 06:16:54.785878  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.028s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.786473  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d): perf score=2.188937
I20260812 06:16:54.804064  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: FlushDeltaMemStoresOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:16:54.804838  1896 maintenance_manager.cc:419] P 051429b4a1054a4fa12142f23505a586: Scheduling MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d): perf score=1.000000
I20260812 06:16:54.875550  1472 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.002s	sys 0.000s
I20260812 06:16:54.876346  1472 tablet_server.cc:179] TabletServer@127.1.112.1:0 shutting down...
I20260812 06:16:54.978750  1826 maintenance_manager.cc:643] P 051429b4a1054a4fa12142f23505a586: MajorDeltaCompactionOp(fce7ab8961744d40beaa3927e026ac9d) complete. Timing: real 0.174s	user 0.130s	sys 0.044s Metrics: {"cfile_cache_hit":241,"cfile_cache_hit_bytes":9808428,"cfile_cache_miss":392,"cfile_cache_miss_bytes":19027827,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1193,"lbm_read_time_us":9597,"lbm_reads_lt_1ms":424,"lbm_write_time_us":34188,"lbm_writes_lt_1ms":643,"mutex_wait_us":474,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":46720,"update_count":3000}
I20260812 06:16:54.980257  1472 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:54.980651  1472 tablet_replica.cc:333] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586: stopping tablet replica
I20260812 06:16:54.980837  1472 raft_consensus.cc:2243] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.981168  1472 raft_consensus.cc:2272] T fce7ab8961744d40beaa3927e026ac9d P 051429b4a1054a4fa12142f23505a586 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.988559  1472 tablet_server.cc:196] TabletServer@127.1.112.1:0 shutdown complete.
I20260812 06:16:55.032500  1472 master.cc:562] Master@127.1.112.62:40749 shutting down...
I20260812 06:16:55.037222  1472 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:55.037463  1472 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:55.037551  1472 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8c190530110f4aafa26e96b28752d83c: stopping tablet replica
I20260812 06:16:55.050551  1472 master.cc:584] Master@127.1.112.62:40749 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6487 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (14291 ms total)

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