[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:33.961696  5597 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.119.126:44899
I20260812 06:18:33.962742  5597 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:33.963418  5597 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.970053  5603 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.970121  5607 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.970213  5605 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:33.970479  5597 server_base.cc:1061] running on GCE node
I20260812 06:18:33.970971  5597 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.971127  5597 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:33.971199  5597 hybrid_clock.cc:648] HybridClock initialized: now 1786515513971196 us; error 0 us; skew 500 ppm
I20260812 06:18:33.973137  5597 webserver.cc:533] Webserver started at http://127.5.119.126:36377/ using document root <none> and password file <none>
I20260812 06:18:33.973712  5597 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.973809  5597 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.974074  5597 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.976202  5597 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/master-0-root/instance:
uuid: "50b168f6e54f47d39f04a3f4a89fc599"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-wl2h"
I20260812 06:18:33.979959  5597 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:33.982295  5616 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.983453  5597 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.983613  5597 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/master-0-root
uuid: "50b168f6e54f47d39f04a3f4a89fc599"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-wl2h"
I20260812 06:18:33.983729  5597 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:34.029747  5597 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.030434  5597 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:34.030628  5597 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.038832  5597 rpc_server.cc:307] RPC server started. Bound to: 127.5.119.126:44899
I20260812 06:18:34.038851  5683 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.119.126:44899 every 8 connection(s)
I20260812 06:18:34.041289  5684 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:34.046662  5684 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: Bootstrap starting.
I20260812 06:18:34.049103  5684 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.050001  5684 log.cc:826] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:34.051828  5684 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: No bootstrap required, opened a new log
I20260812 06:18:34.054646  5684 raft_consensus.cc:359] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER }
I20260812 06:18:34.054816  5684 raft_consensus.cc:385] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.054864  5684 raft_consensus.cc:740] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 50b168f6e54f47d39f04a3f4a89fc599, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.055423  5684 consensus_queue.cc:260] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [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: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER }
I20260812 06:18:34.055558  5684 raft_consensus.cc:399] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.055599  5684 raft_consensus.cc:493] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.055689  5684 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.056481  5684 raft_consensus.cc:515] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER }
I20260812 06:18:34.056872  5684 leader_election.cc:304] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [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: 50b168f6e54f47d39f04a3f4a89fc599; no voters: 
I20260812 06:18:34.057166  5684 leader_election.cc:290] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.057377  5687 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.057673  5687 raft_consensus.cc:697] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 1 LEADER]: Becoming Leader. State: Replica: 50b168f6e54f47d39f04a3f4a89fc599, State: Running, Role: LEADER
I20260812 06:18:34.058090  5687 consensus_queue.cc:237] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [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: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER }
I20260812 06:18:34.058349  5684 sys_catalog.cc:565] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:34.060194  5688 sys_catalog.cc:455] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "50b168f6e54f47d39f04a3f4a89fc599" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER } }
I20260812 06:18:34.060194  5689 sys_catalog.cc:455] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 50b168f6e54f47d39f04a3f4a89fc599. Latest consensus state: current_term: 1 leader_uuid: "50b168f6e54f47d39f04a3f4a89fc599" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50b168f6e54f47d39f04a3f4a89fc599" member_type: VOTER } }
I20260812 06:18:34.060387  5689 sys_catalog.cc:458] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.060387  5688 sys_catalog.cc:458] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.060851  5709 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:34.060887  5597 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:34.063279  5709 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:34.068127  5709 catalog_manager.cc:1383] Generated new cluster ID: c07e704858004a89bf53d990a677f5b5
I20260812 06:18:34.068205  5709 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:34.086483  5709 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:34.087615  5709 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:34.098567  5709 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: Generated new TSK 0
I20260812 06:18:34.099346  5709 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:34.125873  5597 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:34.129072  5715 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:34.129120  5719 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:34.129287  5597 server_base.cc:1061] running on GCE node
W20260812 06:18:34.129140  5716 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:34.129618  5597 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:34.129669  5597 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:34.129686  5597 hybrid_clock.cc:648] HybridClock initialized: now 1786515514129686 us; error 0 us; skew 500 ppm
I20260812 06:18:34.130779  5597 webserver.cc:533] Webserver started at http://127.5.119.65:43427/ using document root <none> and password file <none>
I20260812 06:18:34.130970  5597 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:34.131069  5597 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:34.131167  5597 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:34.131618  5597 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/instance:
uuid: "be28b5fb652744e3aa0607a015908962"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-wl2h"
I20260812 06:18:34.133378  5597 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:34.134490  5725 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.134747  5597 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:34.134822  5597 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root
uuid: "be28b5fb652744e3aa0607a015908962"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-wl2h"
I20260812 06:18:34.134919  5597 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:34.156960  5597 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.157582  5597 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.158159  5597 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:34.159183  5597 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:34.159240  5597 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.159310  5597 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:34.159350  5597 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.166591  5597 rpc_server.cc:307] RPC server started. Bound to: 127.5.119.65:43561
I20260812 06:18:34.166785  5803 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.119.65:43561 every 8 connection(s)
I20260812 06:18:34.180737  5804 heartbeater.cc:344] Connected to a master server at 127.5.119.126:44899
I20260812 06:18:34.181023  5804 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:34.181532  5804 heartbeater.cc:507] Master 127.5.119.126:44899 requested a full tablet report, sending...
I20260812 06:18:34.183136  5635 ts_manager.cc:194] Registered new tserver with Master: be28b5fb652744e3aa0607a015908962 (127.5.119.65:43561)
I20260812 06:18:34.183522  5597 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015786601s
I20260812 06:18:34.184746  5635 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38020
I20260812 06:18:34.194159  5635 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38036:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:34.208917  5758 tablet_service.cc:1511] Processing CreateTablet for tablet ca74385392394a03b3252f577d9c8804 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7390840b480145cfbb2389af472feb37]), partition=
I20260812 06:18:34.209427  5758 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ca74385392394a03b3252f577d9c8804. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:34.212656  5819 tablet_bootstrap.cc:492] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Bootstrap starting.
I20260812 06:18:34.213912  5819 tablet_bootstrap.cc:654] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.215149  5819 tablet_bootstrap.cc:492] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: No bootstrap required, opened a new log
I20260812 06:18:34.215274  5819 ts_tablet_manager.cc:1403] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:34.215794  5819 raft_consensus.cc:359] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be28b5fb652744e3aa0607a015908962" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43561 } }
I20260812 06:18:34.215927  5819 raft_consensus.cc:385] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.216009  5819 raft_consensus.cc:740] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: be28b5fb652744e3aa0607a015908962, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.216188  5819 consensus_queue.cc:260] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [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: "be28b5fb652744e3aa0607a015908962" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43561 } }
I20260812 06:18:34.216280  5819 raft_consensus.cc:399] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.216323  5819 raft_consensus.cc:493] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.216415  5819 raft_consensus.cc:3060] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.217177  5819 raft_consensus.cc:515] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be28b5fb652744e3aa0607a015908962" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43561 } }
I20260812 06:18:34.217338  5819 leader_election.cc:304] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [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: be28b5fb652744e3aa0607a015908962; no voters: 
I20260812 06:18:34.217586  5819 leader_election.cc:290] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.217693  5821 raft_consensus.cc:2804] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.217871  5821 raft_consensus.cc:697] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 1 LEADER]: Becoming Leader. State: Replica: be28b5fb652744e3aa0607a015908962, State: Running, Role: LEADER
I20260812 06:18:34.217957  5819 ts_tablet_manager.cc:1434] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:34.218009  5821 consensus_queue.cc:237] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [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: "be28b5fb652744e3aa0607a015908962" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43561 } }
I20260812 06:18:34.218357  5804 heartbeater.cc:499] Master 127.5.119.126:44899 was elected leader, sending a full tablet report...
I20260812 06:18:34.221328  5635 catalog_manager.cc:5719] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 reported cstate change: term changed from 0 to 1, leader changed from <none> to be28b5fb652744e3aa0607a015908962 (127.5.119.65). New cstate: current_term: 1 leader_uuid: "be28b5fb652744e3aa0607a015908962" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "be28b5fb652744e3aa0607a015908962" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43561 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:34.290025  5597 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.020s	sys 0.010s
I20260812 06:18:34.418382  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushMRSOp(ca74385392394a03b3252f577d9c8804): perf score=15.086190
I20260812 06:18:34.566318  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushMRSOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.147s	user 0.120s	sys 0.023s Metrics: {"bytes_written":9640926,"cfile_init":1,"compiler_manager_pool.queue_time_us":218,"delete_count":0,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1245,"drs_written":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34515,"lbm_writes_lt_1ms":592,"mutex_wait_us":441,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":31360,"thread_start_us":102,"threads_started":1,"update_count":1175}
I20260812 06:18:34.567767  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling LogGCOp(ca74385392394a03b3252f577d9c8804): free 20290830 bytes of WAL
I20260812 06:18:34.568133  5730 log_reader.cc:385] T ca74385392394a03b3252f577d9c8804: removed 2 log segments from log reader
I20260812 06:18:34.568245  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000001 (ops 1-6)
I20260812 06:18:34.568367  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000002 (ops 7-10)
I20260812 06:18:34.573727  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: LogGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:34.574170  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=1.196750
I20260812 06:18:34.602188  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.028s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:18:34.602624  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:34.617029  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.617522  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804): 12308958 bytes on disk
I20260812 06:18:34.618220  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.618754  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:34.770475  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.152s	user 0.126s	sys 0.019s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631399,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":985,"lbm_read_time_us":11107,"lbm_reads_lt_1ms":469,"lbm_write_time_us":23074,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":317,"threads_started":5,"update_count":2000}
I20260812 06:18:34.771212  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:34.820724  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.049s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14929,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.821276  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:34.836615  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.837078  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:34.973325  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.136s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":725,"lbm_read_time_us":8720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24521,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:18:34.973879  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.021135  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13079,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.021840  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:35.156198  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.134s	user 0.090s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":195,"lbm_read_time_us":8583,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22128,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":1500}
I20260812 06:18:35.156917  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.199100  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16409,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.199747  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:35.216140  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.216624  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:35.345503  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.129s	user 0.106s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":305,"lbm_read_time_us":10317,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23355,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2000}
I20260812 06:18:35.346103  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.396615  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.050s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20114,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.397092  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:35.408507  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.408994  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:35.540020  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.131s	user 0.098s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":8990,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26968,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:35.540658  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.591138  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.050s	user 0.031s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17565,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.591831  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:35.602499  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.603228  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:35.749722  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.146s	user 0.102s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3802,"lbm_read_time_us":10814,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23491,"lbm_writes_lt_1ms":443,"mutex_wait_us":2652,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.750362  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.794835  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.044s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16423,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.795348  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:35.806052  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.806913  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:35.938309  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.131s	user 0.082s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":9165,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28931,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:35.938862  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:35.972990  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.034s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14775,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.973544  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:35.986387  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.986840  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushMRSOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:36.018844  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushMRSOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1714,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2030,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:36.020464  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling LogGCOp(ca74385392394a03b3252f577d9c8804): free 120553379 bytes of WAL
I20260812 06:18:36.020789  5730 log_reader.cc:385] T ca74385392394a03b3252f577d9c8804: removed 12 log segments from log reader
I20260812 06:18:36.020860  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000003 (ops 11-15)
I20260812 06:18:36.020901  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000004 (ops 16-20)
I20260812 06:18:36.020925  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000005 (ops 21-24)
I20260812 06:18:36.020947  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000006 (ops 25-29)
I20260812 06:18:36.020974  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000007 (ops 30-34)
I20260812 06:18:36.021004  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000008 (ops 35-39)
I20260812 06:18:36.021030  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000009 (ops 40-44)
I20260812 06:18:36.021060  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000010 (ops 45-48)
I20260812 06:18:36.021090  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000011 (ops 49-53)
I20260812 06:18:36.021116  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000012 (ops 54-58)
I20260812 06:18:36.021149  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000013 (ops 59-63)
I20260812 06:18:36.021183  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000014 (ops 64-68)
I20260812 06:18:36.048718  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: LogGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:36.049167  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=3.181125
I20260812 06:18:36.067528  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6968,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:36.067968  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:36.077637  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.078096  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:36.254647  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.176s	user 0.143s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":986,"lbm_read_time_us":12159,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34276,"lbm_writes_lt_1ms":643,"mutex_wait_us":1787,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22912,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:36.255246  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804): 483 bytes on disk
I20260812 06:18:36.255852  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.256356  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=14.095187
I20260812 06:18:36.315150  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.059s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27358,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.315749  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:36.329538  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.330006  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:36.474892  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.145s	user 0.118s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":8799,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29154,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:36.475672  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=14.095187
I20260812 06:18:36.542775  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.067s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25082,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.543377  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:36.556424  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.556953  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:36.708679  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.151s	user 0.113s	sys 0.038s 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":927,"lbm_read_time_us":11399,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31073,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:18:36.709388  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:36.744637  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14972,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.745312  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:36.760842  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.761380  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:36.885689  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.124s	user 0.102s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":8209,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24057,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:36.886418  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:36.937075  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.050s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17874,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.937752  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:36.955691  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.956370  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:37.103165  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.147s	user 0.110s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1259,"lbm_read_time_us":10692,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26012,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:37.103873  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:37.149462  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.045s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.149998  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:37.161536  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.161993  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:37.290592  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":9123,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25171,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:37.291271  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:37.333844  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.042s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16118,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:37.334391  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:37.345873  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.346560  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushMRSOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:37.376070  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushMRSOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.029s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1368,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1362,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:37.377126  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling LogGCOp(ca74385392394a03b3252f577d9c8804): free 112692317 bytes of WAL
I20260812 06:18:37.377400  5730 log_reader.cc:385] T ca74385392394a03b3252f577d9c8804: removed 11 log segments from log reader
I20260812 06:18:37.377449  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000015 (ops 69-73)
I20260812 06:18:37.377508  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000016 (ops 74-78)
I20260812 06:18:37.377550  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000017 (ops 79-83)
I20260812 06:18:37.377583  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000018 (ops 84-88)
I20260812 06:18:37.377621  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000019 (ops 89-93)
I20260812 06:18:37.377652  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000020 (ops 94-98)
I20260812 06:18:37.377691  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000021 (ops 99-103)
I20260812 06:18:37.377724  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000022 (ops 104-108)
I20260812 06:18:37.377755  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000023 (ops 109-113)
I20260812 06:18:37.377789  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000024 (ops 114-118)
I20260812 06:18:37.377818  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000025 (ops 119-123)
I20260812 06:18:37.404258  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: LogGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.027s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:18:37.404641  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804): 447 bytes on disk
I20260812 06:18:37.405041  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.405692  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=3.181125
I20260812 06:18:37.418555  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4259,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.418977  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling LogGCOp(ca74385392394a03b3252f577d9c8804): free 12017983 bytes of WAL
I20260812 06:18:37.419226  5730 log_reader.cc:385] T ca74385392394a03b3252f577d9c8804: removed 1 log segments from log reader
I20260812 06:18:37.419278  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000026 (ops 124-128)
I20260812 06:18:37.421526  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: LogGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:37.421826  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:37.432139  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3504,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.432590  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:37.601866  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.169s	user 0.136s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":380,"lbm_read_time_us":12793,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33070,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:37.602489  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=14.095187
I20260812 06:18:37.665282  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.062s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23307,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.665815  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:37.677350  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.678073  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:37.825452  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.147s	user 0.099s	sys 0.048s 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":703,"lbm_read_time_us":11108,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31657,"lbm_writes_lt_1ms":543,"mutex_wait_us":296,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:18:37.827734  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:37.871950  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.042s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18582,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:37.872479  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:37.883284  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3848,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.883858  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.018890  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.135s	user 0.106s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":9511,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25345,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":54144,"update_count":2000}
I20260812 06:18:38.019690  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:38.063524  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.044s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19993,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.064201  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.075320  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.076056  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.212265  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.136s	user 0.098s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":9201,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24984,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:18:38.213301  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:38.264046  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.264631  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.275381  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.275830  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.423939  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.148s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":10520,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22709,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:18:38.426937  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:38.467708  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.041s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17052,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.468212  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.481290  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.481986  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.612134  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.130s	user 0.110s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":8645,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25678,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:38.612874  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:38.653152  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18653,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.653769  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.669773  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.670365  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.806094  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.135s	user 0.111s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":302,"lbm_read_time_us":9215,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27366,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28800,"update_count":2000}
I20260812 06:18:38.807132  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=10.126437
I20260812 06:18:38.860167  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.053s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17122,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.860818  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.873142  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.873730  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushMRSOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:38.918874  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushMRSOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.045s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1368,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1583,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:38.919684  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling LogGCOp(ca74385392394a03b3252f577d9c8804): free 120553636 bytes of WAL
I20260812 06:18:38.919922  5730 log_reader.cc:385] T ca74385392394a03b3252f577d9c8804: removed 12 log segments from log reader
I20260812 06:18:38.919963  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000027 (ops 129-133)
I20260812 06:18:38.919991  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000028 (ops 134-138)
I20260812 06:18:38.920053  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000029 (ops 139-142)
I20260812 06:18:38.920095  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000030 (ops 143-147)
I20260812 06:18:38.920135  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000031 (ops 148-152)
I20260812 06:18:38.920174  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000032 (ops 153-157)
I20260812 06:18:38.920213  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000033 (ops 158-162)
I20260812 06:18:38.920497  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000034 (ops 163-167)
I20260812 06:18:38.920573  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000035 (ops 168-172)
I20260812 06:18:38.920608  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000036 (ops 173-177)
I20260812 06:18:38.920656  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000037 (ops 178-182)
I20260812 06:18:38.920687  5730 log.cc:1079] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/ca74385392394a03b3252f577d9c8804/wal-000000038 (ops 183-186)
I20260812 06:18:38.947757  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: LogGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:38.948231  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804): 483 bytes on disk
I20260812 06:18:38.948673  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: UndoDeltaBlockGCOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.949328  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.970784  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.021s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":6927,"lbm_writes_lt_1ms":106,"mutex_wait_us":760,"reinsert_count":0,"update_count":515}
I20260812 06:18:38.971428  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=2.188937
I20260812 06:18:38.982014  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:38.982519  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:39.184829  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.202s	user 0.150s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1191,"lbm_read_time_us":13659,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33151,"lbm_writes_lt_1ms":643,"mutex_wait_us":367,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22528,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:39.185518  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804): perf score=14.095187
I20260812 06:18:39.233049  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: FlushDeltaMemStoresOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.047s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.233719  5806 maintenance_manager.cc:419] P be28b5fb652744e3aa0607a015908962: Scheduling MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804): perf score=1.000000
I20260812 06:18:39.244289  5597 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.954s	user 1.861s	sys 0.142s
I20260812 06:18:39.310297  5597 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.001s	sys 0.000s
I20260812 06:18:39.310961  5597 tablet_server.cc:179] TabletServer@127.5.119.65:0 shutting down...
I20260812 06:18:39.359961  5730 maintenance_manager.cc:643] P be28b5fb652744e3aa0607a015908962: MajorDeltaCompactionOp(ca74385392394a03b3252f577d9c8804) complete. Timing: real 0.126s	user 0.066s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":338,"lbm_read_time_us":10057,"lbm_reads_lt_1ms":459,"lbm_write_time_us":21511,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:18:39.360769  5597 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:39.361187  5597 tablet_replica.cc:333] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962: stopping tablet replica
I20260812 06:18:39.361430  5597 raft_consensus.cc:2243] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.361663  5597 raft_consensus.cc:2272] T ca74385392394a03b3252f577d9c8804 P be28b5fb652744e3aa0607a015908962 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.380254  5597 tablet_server.cc:196] TabletServer@127.5.119.65:0 shutdown complete.
I20260812 06:18:39.403358  5597 master.cc:562] Master@127.5.119.126:44899 shutting down...
I20260812 06:18:39.407083  5597 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.407279  5597 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.407362  5597 tablet_replica.cc:333] T 00000000000000000000000000000000 P 50b168f6e54f47d39f04a3f4a89fc599: stopping tablet replica
I20260812 06:18:39.419989  5597 master.cc:584] Master@127.5.119.126:44899 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5546 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:39.522176  5597 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.119.126:42959
I20260812 06:18:39.522670  5597 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.525027  5842 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:39.525048  5846 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:39.525388  5844 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:39.525396  5597 server_base.cc:1061] running on GCE node
I20260812 06:18:39.525641  5597 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.525683  5597 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:39.525698  5597 hybrid_clock.cc:648] HybridClock initialized: now 1786515519525699 us; error 0 us; skew 500 ppm
I20260812 06:18:39.526614  5597 webserver.cc:533] Webserver started at http://127.5.119.126:38265/ using document root <none> and password file <none>
I20260812 06:18:39.526815  5597 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.526886  5597 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.526976  5597 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.527503  5597 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/master-0-root/instance:
uuid: "0c6a284afffd4f259bced4686cbaf3d2"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-wl2h"
I20260812 06:18:39.529208  5597 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:39.530287  5858 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.530588  5597 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:39.530655  5597 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/master-0-root
uuid: "0c6a284afffd4f259bced4686cbaf3d2"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-wl2h"
I20260812 06:18:39.530745  5597 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:39.542842  5597 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.543354  5597 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.547991  5597 rpc_server.cc:307] RPC server started. Bound to: 127.5.119.126:42959
I20260812 06:18:39.548430  5925 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.119.126:42959 every 8 connection(s)
I20260812 06:18:39.549149  5927 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:39.551062  5927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2: Bootstrap starting.
I20260812 06:18:39.551893  5927 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.553560  5927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2: No bootstrap required, opened a new log
I20260812 06:18:39.554159  5927 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER }
I20260812 06:18:39.554322  5927 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.554382  5927 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0c6a284afffd4f259bced4686cbaf3d2, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.554551  5927 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [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: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER }
I20260812 06:18:39.554658  5927 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.554729  5927 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.554798  5927 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.556025  5927 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER }
I20260812 06:18:39.556190  5927 leader_election.cc:304] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [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: 0c6a284afffd4f259bced4686cbaf3d2; no voters: 
I20260812 06:18:39.556412  5927 leader_election.cc:290] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.556587  5930 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.556820  5930 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 1 LEADER]: Becoming Leader. State: Replica: 0c6a284afffd4f259bced4686cbaf3d2, State: Running, Role: LEADER
I20260812 06:18:39.557013  5927 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:39.556984  5930 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [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: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER }
I20260812 06:18:39.557474  5930 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0c6a284afffd4f259bced4686cbaf3d2. Latest consensus state: current_term: 1 leader_uuid: "0c6a284afffd4f259bced4686cbaf3d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER } }
I20260812 06:18:39.557576  5930 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.558122  5931 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0c6a284afffd4f259bced4686cbaf3d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c6a284afffd4f259bced4686cbaf3d2" member_type: VOTER } }
I20260812 06:18:39.558238  5931 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:39.558809  5934 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:39.560074  5934 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:39.560778  5597 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:39.562484  5934 catalog_manager.cc:1383] Generated new cluster ID: 0993fa54a8034da9ba3656fb49dba36d
I20260812 06:18:39.562541  5934 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:39.573923  5934 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:39.574563  5934 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:39.579782  5934 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2: Generated new TSK 0
I20260812 06:18:39.579999  5934 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:39.593307  5597 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:39.595602  5950 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:39.595620  5597 server_base.cc:1061] running on GCE node
W20260812 06:18:39.595602  5951 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:39.595712  5953 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:39.596020  5597 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:39.596064  5597 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:39.596081  5597 hybrid_clock.cc:648] HybridClock initialized: now 1786515519596081 us; error 0 us; skew 500 ppm
I20260812 06:18:39.596973  5597 webserver.cc:533] Webserver started at http://127.5.119.65:34143/ using document root <none> and password file <none>
I20260812 06:18:39.597126  5597 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:39.597178  5597 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:39.597241  5597 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:39.597623  5597 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/instance:
uuid: "6416001d1a704b3b903cc82e354d3efd"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-wl2h"
I20260812 06:18:39.599243  5597 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:39.600172  5961 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.600401  5597 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:39.600463  5597 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root
uuid: "6416001d1a704b3b903cc82e354d3efd"
format_stamp: "Formatted at 2026-08-12 06:18:39 on dist-test-slave-wl2h"
I20260812 06:18:39.600605  5597 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:39.612643  5597 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:39.613080  5597 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:39.613413  5597 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:39.613898  5597 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:39.613935  5597 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.613996  5597 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:39.614035  5597 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:39.618501  5597 rpc_server.cc:307] RPC server started. Bound to: 127.5.119.65:43399
I20260812 06:18:39.618880  6042 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.119.65:43399 every 8 connection(s)
I20260812 06:18:39.628535  6043 heartbeater.cc:344] Connected to a master server at 127.5.119.126:42959
I20260812 06:18:39.628656  6043 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:39.628886  6043 heartbeater.cc:507] Master 127.5.119.126:42959 requested a full tablet report, sending...
I20260812 06:18:39.629544  5881 ts_manager.cc:194] Registered new tserver with Master: 6416001d1a704b3b903cc82e354d3efd (127.5.119.65:43399)
I20260812 06:18:39.630271  5597 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011170019s
I20260812 06:18:39.630329  5881 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33834
I20260812 06:18:39.638481  5881 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33846:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:39.647361  5996 tablet_service.cc:1511] Processing CreateTablet for tablet c1a6c6ec2ddc4305b610c83f5ea85d81 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f52128fc6739414bbb2f048b9a4543fa]), partition=
I20260812 06:18:39.647678  5996 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c1a6c6ec2ddc4305b610c83f5ea85d81. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:39.649900  6060 tablet_bootstrap.cc:492] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Bootstrap starting.
I20260812 06:18:39.650771  6060 tablet_bootstrap.cc:654] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:39.652635  6060 tablet_bootstrap.cc:492] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: No bootstrap required, opened a new log
I20260812 06:18:39.652765  6060 ts_tablet_manager.cc:1403] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:39.653234  6060 raft_consensus.cc:359] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6416001d1a704b3b903cc82e354d3efd" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43399 } }
I20260812 06:18:39.653354  6060 raft_consensus.cc:385] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:39.653406  6060 raft_consensus.cc:740] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6416001d1a704b3b903cc82e354d3efd, State: Initialized, Role: FOLLOWER
I20260812 06:18:39.653532  6060 consensus_queue.cc:260] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [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: "6416001d1a704b3b903cc82e354d3efd" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43399 } }
I20260812 06:18:39.653607  6060 raft_consensus.cc:399] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:39.653630  6060 raft_consensus.cc:493] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:39.653664  6060 raft_consensus.cc:3060] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:39.654400  6060 raft_consensus.cc:515] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6416001d1a704b3b903cc82e354d3efd" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43399 } }
I20260812 06:18:39.654515  6060 leader_election.cc:304] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [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: 6416001d1a704b3b903cc82e354d3efd; no voters: 
I20260812 06:18:39.654700  6060 leader_election.cc:290] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:39.654866  6065 raft_consensus.cc:2804] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:39.655007  6060 ts_tablet_manager.cc:1434] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:39.655052  6043 heartbeater.cc:499] Master 127.5.119.126:42959 was elected leader, sending a full tablet report...
I20260812 06:18:39.655103  6065 raft_consensus.cc:697] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 1 LEADER]: Becoming Leader. State: Replica: 6416001d1a704b3b903cc82e354d3efd, State: Running, Role: LEADER
I20260812 06:18:39.655264  6065 consensus_queue.cc:237] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [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: "6416001d1a704b3b903cc82e354d3efd" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43399 } }
I20260812 06:18:39.656608  5881 catalog_manager.cc:5719] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd reported cstate change: term changed from 0 to 1, leader changed from <none> to 6416001d1a704b3b903cc82e354d3efd (127.5.119.65). New cstate: current_term: 1 leader_uuid: "6416001d1a704b3b903cc82e354d3efd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6416001d1a704b3b903cc82e354d3efd" member_type: VOTER last_known_addr { host: "127.5.119.65" port: 43399 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:39.718861  5597 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.006s
I20260812 06:18:39.869665  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=19.054940
I20260812 06:18:40.027712  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.158s	user 0.122s	sys 0.035s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":918,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42298,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:40.028419  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): free 20743880 bytes of WAL
I20260812 06:18:40.028760  5966 log_reader.cc:385] T c1a6c6ec2ddc4305b610c83f5ea85d81: removed 2 log segments from log reader
I20260812 06:18:40.028838  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000001 (ops 1-6)
I20260812 06:18:40.028898  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000002 (ops 7-11)
I20260812 06:18:40.034838  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.006s	user 0.004s	sys 0.000s Metrics: {}
I20260812 06:18:40.035444  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): 16411393 bytes on disk
I20260812 06:18:40.036253  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.036839  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.074604  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.037s	user 0.002s	sys 0.019s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.075253  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.086923  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.087508  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:40.273679  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.186s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1534,"lbm_read_time_us":13274,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28572,"lbm_writes_lt_1ms":543,"mutex_wait_us":366,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":338,"threads_started":5,"update_count":2500}
I20260812 06:18:40.274135  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:40.326314  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.052s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18813,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.326894  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.342864  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.343421  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:40.536300  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.193s	user 0.094s	sys 0.094s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":495,"lbm_read_time_us":12631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31415,"lbm_writes_lt_1ms":543,"mutex_wait_us":236,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:40.537026  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=11.118625
I20260812 06:18:40.574347  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.037s	user 0.009s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16009,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:40.574918  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.591689  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6419,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.592168  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:40.723605  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.131s	user 0.106s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1443,"lbm_read_time_us":8263,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26602,"lbm_writes_lt_1ms":443,"mutex_wait_us":403,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:40.724148  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:40.758807  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.035s	user 0.013s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14842,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.759514  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.775593  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.776165  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:40.905413  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.129s	user 0.114s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"lbm_read_time_us":7734,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24559,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:18:40.906023  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:40.939148  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.033s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13132,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.939674  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:40.955272  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.955706  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:41.083389  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.128s	user 0.116s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":9520,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23688,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:18:41.083889  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:41.134956  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.051s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.135639  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:41.152709  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.153388  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:41.307063  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.153s	user 0.114s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":840,"lbm_read_time_us":11598,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22854,"lbm_writes_lt_1ms":443,"mutex_wait_us":105,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39168,"update_count":2000}
I20260812 06:18:41.307789  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:41.350402  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15997,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":1500}
I20260812 06:18:41.350919  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:41.362947  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.363448  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:41.393103  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1639,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:41.393698  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): free 121006431 bytes of WAL
I20260812 06:18:41.393929  5966 log_reader.cc:385] T c1a6c6ec2ddc4305b610c83f5ea85d81: removed 12 log segments from log reader
I20260812 06:18:41.393970  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000003 (ops 12-16)
I20260812 06:18:41.393998  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000004 (ops 17-20)
I20260812 06:18:41.394060  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000005 (ops 21-25)
I20260812 06:18:41.394101  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000006 (ops 26-30)
I20260812 06:18:41.394140  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000007 (ops 31-35)
I20260812 06:18:41.394203  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000008 (ops 36-40)
I20260812 06:18:41.394246  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000009 (ops 41-45)
I20260812 06:18:41.394282  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000010 (ops 46-50)
I20260812 06:18:41.394320  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000011 (ops 51-55)
I20260812 06:18:41.394358  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000012 (ops 56-60)
I20260812 06:18:41.394398  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000013 (ops 61-65)
I20260812 06:18:41.394435  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000014 (ops 66-70)
I20260812 06:18:41.421216  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:41.421865  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): 472 bytes on disk
I20260812 06:18:41.422462  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.422982  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=3.181125
I20260812 06:18:41.444712  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.022s	user 0.012s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4578,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.445266  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:41.455686  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.456135  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:41.667124  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.211s	user 0.133s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2908,"lbm_read_time_us":14391,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34365,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:41.667721  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:41.732573  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.065s	user 0.036s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23661,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.733212  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:41.750659  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.751310  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:41.951668  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.200s	user 0.143s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":447,"lbm_read_time_us":14893,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29353,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:18:41.952493  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:42.006970  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.054s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.007615  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:42.020429  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.020951  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:42.203950  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.183s	user 0.140s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1201,"lbm_read_time_us":10480,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28891,"lbm_writes_lt_1ms":543,"mutex_wait_us":445,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:42.204504  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:42.254717  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.050s	user 0.021s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21806,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.255221  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:42.270588  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.271168  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:42.443413  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.172s	user 0.117s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":9672,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31049,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:42.444172  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:42.492997  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.049s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21195,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.493511  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:42.506745  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.507336  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:42.668437  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.161s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":9328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29952,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31104,"update_count":2500}
I20260812 06:18:42.669245  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:42.718422  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.049s	user 0.037s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19285,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.718911  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:42.731372  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.732088  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:42.893761  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.161s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1017,"lbm_read_time_us":10586,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32137,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:18:42.894383  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:42.947715  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.053s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20112,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.948381  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:42.960304  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.960858  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:42.992578  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":480,"dirs.run_wall_time_us":1671,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:42.993467  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): free 136275199 bytes of WAL
I20260812 06:18:42.993727  5966 log_reader.cc:385] T c1a6c6ec2ddc4305b610c83f5ea85d81: removed 13 log segments from log reader
I20260812 06:18:42.993803  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000015 (ops 71-75)
I20260812 06:18:42.993858  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000016 (ops 76-80)
I20260812 06:18:42.993899  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000017 (ops 81-84)
I20260812 06:18:42.993937  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000018 (ops 85-89)
I20260812 06:18:42.993973  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000019 (ops 90-94)
I20260812 06:18:42.994010  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000020 (ops 95-99)
I20260812 06:18:42.994047  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000021 (ops 100-104)
I20260812 06:18:42.994084  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000022 (ops 105-109)
I20260812 06:18:42.994120  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000023 (ops 110-114)
I20260812 06:18:42.994158  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000024 (ops 115-119)
I20260812 06:18:42.994192  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000025 (ops 120-124)
I20260812 06:18:42.994228  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000026 (ops 125-129)
I20260812 06:18:42.994266  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000027 (ops 130-134)
I20260812 06:18:43.023126  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:43.023566  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=4.173312
I20260812 06:18:43.042315  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":6030800,"delete_count":0,"lbm_write_time_us":7483,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 06:18:43.042896  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.196750
I20260812 06:18:43.051919  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2174479,"delete_count":0,"lbm_write_time_us":2496,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:18:43.052382  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:43.249423  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.197s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979706,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1031,"lbm_read_time_us":14122,"lbm_reads_lt_1ms":770,"lbm_write_time_us":42097,"lbm_writes_lt_1ms":743,"mutex_wait_us":303,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17536,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:43.249934  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=14.095187
I20260812 06:18:43.298938  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.049s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19486,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.299407  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:43.315121  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.315630  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): 493 bytes on disk
I20260812 06:18:43.316058  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.316556  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:43.474296  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.158s	user 0.129s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":10132,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32567,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:18:43.475072  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=11.118625
I20260812 06:18:43.506103  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13530,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.506670  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:43.521458  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.522073  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:43.674819  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.153s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":10612,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25024,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:18:43.676026  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=11.118625
I20260812 06:18:43.709892  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.034s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12553635,"delete_count":0,"lbm_write_time_us":14553,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:18:43.710477  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:43.725252  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":5761,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:43.725811  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:43.856271  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.130s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":9134,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25467,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:43.857023  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:43.896605  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.039s	user 0.016s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16173,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:43.897081  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:43.908334  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4049,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.908861  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.043349  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.134s	user 0.097s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":10323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25911,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:44.044132  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:44.088979  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.045s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15515,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.089447  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:44.099975  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.100488  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.235368  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.135s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1111,"lbm_read_time_us":9892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25666,"lbm_writes_lt_1ms":443,"mutex_wait_us":388,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31744,"update_count":2000}
I20260812 06:18:44.236057  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:44.292488  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.056s	user 0.014s	sys 0.035s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18215,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.293097  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:44.304229  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.304703  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.452976  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.148s	user 0.090s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":10569,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25698,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.453677  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=10.126437
I20260812 06:18:44.506729  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.053s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18247,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.507438  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=2.188937
I20260812 06:18:44.519384  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.520069  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.552649  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushMRSOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.032s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1409,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1868,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:44.553300  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): free 128867735 bytes of WAL
I20260812 06:18:44.553525  5966 log_reader.cc:385] T c1a6c6ec2ddc4305b610c83f5ea85d81: removed 13 log segments from log reader
I20260812 06:18:44.553566  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000028 (ops 135-139)
I20260812 06:18:44.553596  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000029 (ops 140-144)
I20260812 06:18:44.553663  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000030 (ops 145-148)
I20260812 06:18:44.553689  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000031 (ops 149-153)
I20260812 06:18:44.553728  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000032 (ops 154-158)
I20260812 06:18:44.553767  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000033 (ops 159-163)
I20260812 06:18:44.553804  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000034 (ops 164-168)
I20260812 06:18:44.553845  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000035 (ops 169-173)
I20260812 06:18:44.553884  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000036 (ops 174-178)
I20260812 06:18:44.553922  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000037 (ops 179-182)
I20260812 06:18:44.553956  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000038 (ops 183-187)
I20260812 06:18:44.553995  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000039 (ops 188-192)
I20260812 06:18:44.554033  5966 log.cc:1079] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: Deleting log segment in path: /tmp/dist-test-task2vk4Eq/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513950739-5597-0/minicluster-data/ts-0-root/wals/c1a6c6ec2ddc4305b610c83f5ea85d81/wal-000000040 (ops 193-196)
I20260812 06:18:44.583214  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: LogGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:44.583609  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81): 482 bytes on disk
I20260812 06:18:44.584012  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: UndoDeltaBlockGCOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.584519  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=4.173312
I20260812 06:18:44.608668  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":6332,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:18:44.609193  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.616241  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: FlushDeltaMemStoresOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.007s	user 0.001s	sys 0.005s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":2315,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:18:44.616737  6044 maintenance_manager.cc:419] P 6416001d1a704b3b903cc82e354d3efd: Scheduling MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81): perf score=1.000000
I20260812 06:18:44.663969  5597 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.945s	user 1.857s	sys 0.198s
I20260812 06:18:44.758570  5597 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.000s	sys 0.000s
I20260812 06:18:44.759254  5597 tablet_server.cc:179] TabletServer@127.5.119.65:0 shutting down...
I20260812 06:18:44.798691  5966 maintenance_manager.cc:643] P 6416001d1a704b3b903cc82e354d3efd: MajorDeltaCompactionOp(c1a6c6ec2ddc4305b610c83f5ea85d81) complete. Timing: real 0.182s	user 0.119s	sys 0.062s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877289,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":615,"lbm_read_time_us":13660,"lbm_reads_lt_1ms":670,"lbm_write_time_us":28389,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":113,"threads_started":1,"update_count":3000}
I20260812 06:18:44.799670  5597 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:44.800067  5597 tablet_replica.cc:333] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd: stopping tablet replica
I20260812 06:18:44.800222  5597 raft_consensus.cc:2243] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.800392  5597 raft_consensus.cc:2272] T c1a6c6ec2ddc4305b610c83f5ea85d81 P 6416001d1a704b3b903cc82e354d3efd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.806361  5597 tablet_server.cc:196] TabletServer@127.5.119.65:0 shutdown complete.
I20260812 06:18:44.855377  5597 master.cc:562] Master@127.5.119.126:42959 shutting down...
I20260812 06:18:44.859149  5597 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:44.859382  5597 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:44.859443  5597 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0c6a284afffd4f259bced4686cbaf3d2: stopping tablet replica
I20260812 06:18:44.872375  5597 master.cc:584] Master@127.5.119.126:42959 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5452 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10999 ms total)

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