[==========] 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:43.922129  8791 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.149.254:39417
I20260812 06:18:43.923164  8791 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:43.923794  8791 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.930048  8798 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:43.930099  8797 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:43.930217  8791 server_base.cc:1061] running on GCE node
W20260812 06:18:43.930387  8800 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:43.930860  8791 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.930967  8791 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:43.931010  8791 hybrid_clock.cc:648] HybridClock initialized: now 1786515523931007 us; error 0 us; skew 500 ppm
I20260812 06:18:43.932770  8791 webserver.cc:533] Webserver started at http://127.8.149.254:39611/ using document root <none> and password file <none>
I20260812 06:18:43.933285  8791 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.933351  8791 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.933593  8791 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.935212  8791 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/master-0-root/instance:
uuid: "28f18da6f86b451cabf24a40669e17af"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-21b9"
I20260812 06:18:43.938639  8791 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:43.940761  8806 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:43.941787  8791 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:43.941905  8791 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/master-0-root
uuid: "28f18da6f86b451cabf24a40669e17af"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-21b9"
I20260812 06:18:43.942003  8791 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-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:43.957023  8791 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.957682  8791 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:43.957854  8791 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.965782  8899 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.149.254:39417 every 8 connection(s)
I20260812 06:18:43.965778  8791 rpc_server.cc:307] RPC server started. Bound to: 127.8.149.254:39417
I20260812 06:18:43.968219  8900 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:43.973592  8900 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: Bootstrap starting.
I20260812 06:18:43.975908  8900 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.976814  8900 log.cc:826] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:43.978559  8900 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: No bootstrap required, opened a new log
I20260812 06:18:43.981431  8900 raft_consensus.cc:359] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER }
I20260812 06:18:43.981614  8900 raft_consensus.cc:385] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.981664  8900 raft_consensus.cc:740] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 28f18da6f86b451cabf24a40669e17af, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.982267  8900 consensus_queue.cc:260] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [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: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER }
I20260812 06:18:43.982407  8900 raft_consensus.cc:399] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.982467  8900 raft_consensus.cc:493] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.982596  8900 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.983398  8900 raft_consensus.cc:515] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER }
I20260812 06:18:43.983830  8900 leader_election.cc:304] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [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: 28f18da6f86b451cabf24a40669e17af; no voters: 
I20260812 06:18:43.984148  8900 leader_election.cc:290] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.984261  8907 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.984467  8907 raft_consensus.cc:697] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 1 LEADER]: Becoming Leader. State: Replica: 28f18da6f86b451cabf24a40669e17af, State: Running, Role: LEADER
I20260812 06:18:43.984845  8907 consensus_queue.cc:237] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [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: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER }
I20260812 06:18:43.985081  8900 sys_catalog.cc:565] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.986680  8909 sys_catalog.cc:455] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [sys.catalog]: SysCatalogTable state changed. Reason: New leader 28f18da6f86b451cabf24a40669e17af. Latest consensus state: current_term: 1 leader_uuid: "28f18da6f86b451cabf24a40669e17af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER } }
I20260812 06:18:43.986706  8908 sys_catalog.cc:455] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "28f18da6f86b451cabf24a40669e17af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28f18da6f86b451cabf24a40669e17af" member_type: VOTER } }
I20260812 06:18:43.986811  8909 sys_catalog.cc:458] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.986811  8908 sys_catalog.cc:458] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.987152  8931 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.987306  8791 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.989401  8931 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.994031  8931 catalog_manager.cc:1383] Generated new cluster ID: 91d1ce153e514858b12c7f899fc585a1
I20260812 06:18:43.994158  8931 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:44.013062  8931 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:44.014348  8931 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:44.028959  8931 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: Generated new TSK 0
I20260812 06:18:44.029767  8931 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:44.052211  8791 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:44.055130  8949 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:44.055326  8944 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:44.055160  8943 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:44.055471  8791 server_base.cc:1061] running on GCE node
I20260812 06:18:44.055750  8791 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:44.055799  8791 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:44.055812  8791 hybrid_clock.cc:648] HybridClock initialized: now 1786515524055813 us; error 0 us; skew 500 ppm
I20260812 06:18:44.056716  8791 webserver.cc:533] Webserver started at http://127.8.149.193:46133/ using document root <none> and password file <none>
I20260812 06:18:44.056888  8791 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:44.056946  8791 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:44.057026  8791 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:44.057415  8791 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/instance:
uuid: "0056747ea1b1440a88d3528fea7a8bb7"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-21b9"
I20260812 06:18:44.058835  8791 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:44.059787  8958 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:44.060001  8791 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:44.060078  8791 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root
uuid: "0056747ea1b1440a88d3528fea7a8bb7"
format_stamp: "Formatted at 2026-08-12 06:18:44 on dist-test-slave-21b9"
I20260812 06:18:44.060150  8791 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-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:44.080276  8791 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:44.080722  8791 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:44.081239  8791 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:44.082124  8791 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:44.082183  8791 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.082232  8791 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:44.082261  8791 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:44.088714  8791 rpc_server.cc:307] RPC server started. Bound to: 127.8.149.193:43571
I20260812 06:18:44.088753  9077 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.149.193:43571 every 8 connection(s)
I20260812 06:18:44.101704  9079 heartbeater.cc:344] Connected to a master server at 127.8.149.254:39417
I20260812 06:18:44.101948  9079 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:44.102388  9079 heartbeater.cc:507] Master 127.8.149.254:39417 requested a full tablet report, sending...
I20260812 06:18:44.103749  8832 ts_manager.cc:194] Registered new tserver with Master: 0056747ea1b1440a88d3528fea7a8bb7 (127.8.149.193:43571)
I20260812 06:18:44.103910  8791 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014572106s
I20260812 06:18:44.105166  8832 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:32802
I20260812 06:18:44.112990  8832 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:32816:
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:44.126155  9004 tablet_service.cc:1511] Processing CreateTablet for tablet 300a786033724ca59d8b0e5e1b53cabe (DEFAULT_TABLE table=heavy-update-compaction-test [id=8b0397cba6664946b3abc0423371c0a6]), partition=
I20260812 06:18:44.126600  9004 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 300a786033724ca59d8b0e5e1b53cabe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:44.129032  9094 tablet_bootstrap.cc:492] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Bootstrap starting.
I20260812 06:18:44.130209  9094 tablet_bootstrap.cc:654] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:44.131522  9094 tablet_bootstrap.cc:492] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: No bootstrap required, opened a new log
I20260812 06:18:44.131628  9094 ts_tablet_manager.cc:1403] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:44.132076  9094 raft_consensus.cc:359] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0056747ea1b1440a88d3528fea7a8bb7" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 43571 } }
I20260812 06:18:44.132179  9094 raft_consensus.cc:385] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:44.132210  9094 raft_consensus.cc:740] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0056747ea1b1440a88d3528fea7a8bb7, State: Initialized, Role: FOLLOWER
I20260812 06:18:44.132334  9094 consensus_queue.cc:260] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [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: "0056747ea1b1440a88d3528fea7a8bb7" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 43571 } }
I20260812 06:18:44.132406  9094 raft_consensus.cc:399] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:44.132450  9094 raft_consensus.cc:493] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:44.132496  9094 raft_consensus.cc:3060] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:44.133184  9094 raft_consensus.cc:515] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0056747ea1b1440a88d3528fea7a8bb7" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 43571 } }
I20260812 06:18:44.133313  9094 leader_election.cc:304] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [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: 0056747ea1b1440a88d3528fea7a8bb7; no voters: 
I20260812 06:18:44.133504  9094 leader_election.cc:290] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:44.133630  9097 raft_consensus.cc:2804] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:44.133834  9094 ts_tablet_manager.cc:1434] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:44.133853  9097 raft_consensus.cc:697] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 1 LEADER]: Becoming Leader. State: Replica: 0056747ea1b1440a88d3528fea7a8bb7, State: Running, Role: LEADER
I20260812 06:18:44.134083  9079 heartbeater.cc:499] Master 127.8.149.254:39417 was elected leader, sending a full tablet report...
I20260812 06:18:44.134195  9097 consensus_queue.cc:237] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [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: "0056747ea1b1440a88d3528fea7a8bb7" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 43571 } }
I20260812 06:18:44.136842  8832 catalog_manager.cc:5719] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0056747ea1b1440a88d3528fea7a8bb7 (127.8.149.193). New cstate: current_term: 1 leader_uuid: "0056747ea1b1440a88d3528fea7a8bb7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0056747ea1b1440a88d3528fea7a8bb7" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 43571 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:44.197018  8791 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.013s	sys 0.012s
I20260812 06:18:44.339856  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe): perf score=19.054940
I20260812 06:18:44.520450  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.180s	user 0.149s	sys 0.028s Metrics: {"bytes_written":11979286,"cfile_init":1,"compiler_manager_pool.queue_time_us":205,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":729,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43074,"lbm_writes_lt_1ms":759,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":330624,"thread_start_us":114,"threads_started":1,"update_count":1460}
I20260812 06:18:44.521627  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling LogGCOp(300a786033724ca59d8b0e5e1b53cabe): free 20743880 bytes of WAL
I20260812 06:18:44.522010  8965 log_reader.cc:385] T 300a786033724ca59d8b0e5e1b53cabe: removed 2 log segments from log reader
I20260812 06:18:44.522118  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000001 (ops 1-6)
I20260812 06:18:44.522192  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000002 (ops 7-11)
I20260812 06:18:44.526845  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: LogGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:44.527318  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=3.181125
I20260812 06:18:44.551797  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4430853,"delete_count":0,"lbm_write_time_us":6627,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:44.552297  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:44.566073  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.566587  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:44.728308  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.162s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405539,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":503,"lbm_read_time_us":11718,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27007,"lbm_writes_lt_1ms":533,"mutex_wait_us":43,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":300,"threads_started":5,"update_count":2450}
I20260812 06:18:44.728871  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:44.772128  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.043s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13611,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.772578  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe): 16821646 bytes on disk
I20260812 06:18:44.773038  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.773430  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:44.784195  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.784816  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:44.898123  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.113s	user 0.099s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":361,"lbm_read_time_us":7376,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21637,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:18:44.898613  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:44.942026  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.043s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15035,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.942606  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:44.953349  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.954003  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.077000  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.123s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":7883,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22936,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:45.077601  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:45.111438  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.034s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12848,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.111919  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:45.122682  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.123452  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.234162  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.111s	user 0.098s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":7880,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20665,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:45.234681  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:45.276396  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.042s	user 0.011s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13871,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.276903  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:45.287020  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.287458  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.423787  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.136s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":10262,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21053,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:45.424238  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:45.461017  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.037s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14961,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:45.461488  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.565435  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.104s	user 0.087s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":560,"lbm_read_time_us":7262,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18327,"lbm_writes_lt_1ms":343,"mutex_wait_us":253,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.565920  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:45.606308  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15654,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.606884  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:45.616991  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.617625  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.737064  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.119s	user 0.097s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1070,"lbm_read_time_us":8393,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21977,"lbm_writes_lt_1ms":443,"mutex_wait_us":260,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:45.737648  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:45.782689  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.045s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13489,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.783331  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:45.793792  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.794325  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.827106  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.033s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1207,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:45.828053  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe): 482 bytes on disk
I20260812 06:18:45.828568  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.829133  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:45.962713  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.133s	user 0.077s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1396,"lbm_read_time_us":8676,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22006,"lbm_writes_lt_1ms":443,"mutex_wait_us":488,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.963369  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling LogGCOp(300a786033724ca59d8b0e5e1b53cabe): free 133024314 bytes of WAL
I20260812 06:18:45.963610  8965 log_reader.cc:385] T 300a786033724ca59d8b0e5e1b53cabe: removed 13 log segments from log reader
I20260812 06:18:45.963663  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000003 (ops 12-16)
I20260812 06:18:45.963707  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000004 (ops 17-20)
I20260812 06:18:45.963747  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000005 (ops 21-25)
I20260812 06:18:45.963773  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000006 (ops 26-30)
I20260812 06:18:45.963806  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000007 (ops 31-35)
I20260812 06:18:45.963835  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000008 (ops 36-40)
I20260812 06:18:45.963863  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000009 (ops 41-45)
I20260812 06:18:45.963905  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000010 (ops 46-50)
I20260812 06:18:45.963938  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000011 (ops 51-55)
I20260812 06:18:45.963966  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000012 (ops 56-60)
I20260812 06:18:45.963996  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000013 (ops 61-65)
I20260812 06:18:45.964025  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000014 (ops 66-70)
I20260812 06:18:45.964056  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000015 (ops 71-75)
I20260812 06:18:45.991909  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: LogGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:45.992348  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=14.095187
I20260812 06:18:46.041270  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.049s	user 0.031s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20064,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.041766  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.052237  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.052891  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:46.198554  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.145s	user 0.117s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9404,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29624,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:46.199143  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=11.118625
I20260812 06:18:46.239230  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.040s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16888,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.239789  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.258754  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5331,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.259186  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.269392  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.269836  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:46.413532  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.143s	user 0.118s	sys 0.018s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":751,"lbm_read_time_us":9340,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28162,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:46.414060  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=11.118625
I20260812 06:18:46.447391  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.033s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14108,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.448104  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.462532  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.462921  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:46.582379  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.119s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":54,"lbm_read_time_us":6696,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25513,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:18:46.582968  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:46.619102  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.036s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.619635  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.630170  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.630765  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:46.747365  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.116s	user 0.083s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":7563,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22174,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2000}
I20260812 06:18:46.748085  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:46.789964  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.042s	user 0.012s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13216,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.790519  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:46.805652  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.806144  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:46.947818  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.141s	user 0.091s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":9992,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22522,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:18:46.948318  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:46.996379  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.048s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16600,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.996826  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.007241  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.007854  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:47.128729  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.121s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":8303,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22608,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:18:47.129271  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:47.165997  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.037s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13317,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.166514  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.177155  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.178030  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:47.208410  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1216,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1877,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:47.209093  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling LogGCOp(300a786033724ca59d8b0e5e1b53cabe): free 120553453 bytes of WAL
I20260812 06:18:47.209326  8965 log_reader.cc:385] T 300a786033724ca59d8b0e5e1b53cabe: removed 12 log segments from log reader
I20260812 06:18:47.209374  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000016 (ops 76-80)
I20260812 06:18:47.209401  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000017 (ops 81-84)
I20260812 06:18:47.209429  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000018 (ops 85-89)
I20260812 06:18:47.209457  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000019 (ops 90-94)
I20260812 06:18:47.209489  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000020 (ops 95-99)
I20260812 06:18:47.209522  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000021 (ops 100-104)
I20260812 06:18:47.209553  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000022 (ops 105-109)
I20260812 06:18:47.209584  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000023 (ops 110-114)
I20260812 06:18:47.209615  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000024 (ops 115-119)
I20260812 06:18:47.209646  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000025 (ops 120-124)
I20260812 06:18:47.209677  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000026 (ops 125-128)
I20260812 06:18:47.209708  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000027 (ops 129-133)
I20260812 06:18:47.230990  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: LogGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:47.231487  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=3.181125
I20260812 06:18:47.245253  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:47.245738  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe): 473 bytes on disk
I20260812 06:18:47.246142  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.246692  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.256093  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3254,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.256625  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:47.418331  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.161s	user 0.127s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":673,"lbm_read_time_us":11993,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31838,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:47.421321  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=14.095187
I20260812 06:18:47.462509  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.463066  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.480602  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.017s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.481119  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:47.633037  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.152s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":8222,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28727,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:18:47.633572  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=14.095187
I20260812 06:18:47.677245  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.044s	user 0.032s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19001,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.677810  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:47.811772  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.134s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":115,"lbm_read_time_us":8232,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22960,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:47.812287  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=10.126437
I20260812 06:18:47.847008  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12965,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.847819  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.875630  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.028s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6982,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.876135  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:47.886241  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.886909  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:48.065194  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.178s	user 0.116s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":894,"lbm_read_time_us":9717,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27513,"lbm_writes_lt_1ms":543,"mutex_wait_us":235,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":110848,"update_count":2500}
I20260812 06:18:48.065765  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=14.095187
I20260812 06:18:48.107427  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.041s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17403,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.107944  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:48.123025  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.123562  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:48.279203  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.155s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":9138,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28991,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.279772  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=14.095187
I20260812 06:18:48.328905  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.049s	user 0.035s	sys 0.007s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":18815,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.329506  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:48.340833  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.341415  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:48.483155  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.141s	user 0.115s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":592,"lbm_read_time_us":10719,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26905,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:48.483692  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=11.118625
I20260812 06:18:48.513497  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.030s	user 0.014s	sys 0.013s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12321,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.514041  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:48.528316  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:48.528856  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:48.566612  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushMRSOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.038s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1723,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:48.567456  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=3.181125
I20260812 06:18:48.585445  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4430858,"delete_count":0,"lbm_write_time_us":6426,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:48.585934  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling LogGCOp(300a786033724ca59d8b0e5e1b53cabe): free 133024653 bytes of WAL
I20260812 06:18:48.586207  8965 log_reader.cc:385] T 300a786033724ca59d8b0e5e1b53cabe: removed 13 log segments from log reader
I20260812 06:18:48.586280  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000028 (ops 134-138)
I20260812 06:18:48.586319  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000029 (ops 139-142)
I20260812 06:18:48.586355  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000030 (ops 143-147)
I20260812 06:18:48.586390  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000031 (ops 148-152)
I20260812 06:18:48.586421  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000032 (ops 153-157)
I20260812 06:18:48.586447  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000033 (ops 158-162)
I20260812 06:18:48.586474  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000034 (ops 163-167)
I20260812 06:18:48.586503  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000035 (ops 168-172)
I20260812 06:18:48.586535  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000036 (ops 173-177)
I20260812 06:18:48.586575  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000037 (ops 178-182)
I20260812 06:18:48.586683  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000038 (ops 183-187)
I20260812 06:18:48.586728  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000039 (ops 188-192)
I20260812 06:18:48.586752  8965 log.cc:1079] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/300a786033724ca59d8b0e5e1b53cabe/wal-000000040 (ops 193-197)
I20260812 06:18:48.613554  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: LogGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:48.613983  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:48.625819  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.626295  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe): 482 bytes on disk
I20260812 06:18:48.626721  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: UndoDeltaBlockGCOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.627343  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe): perf score=2.188937
I20260812 06:18:48.648636  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: FlushDeltaMemStoresOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.021s	user 0.012s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.649174  9081 maintenance_manager.cc:419] P 0056747ea1b1440a88d3528fea7a8bb7: Scheduling MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe): perf score=1.000000
I20260812 06:18:48.701507  8791 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.504s	user 1.665s	sys 0.103s
I20260812 06:18:48.812626  8791 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.110s	user 0.004s	sys 0.000s
I20260812 06:18:48.813344  8791 tablet_server.cc:179] TabletServer@127.8.149.193:0 shutting down...
I20260812 06:18:48.846802  8965 maintenance_manager.cc:643] P 0056747ea1b1440a88d3528fea7a8bb7: MajorDeltaCompactionOp(300a786033724ca59d8b0e5e1b53cabe) complete. Timing: real 0.197s	user 0.133s	sys 0.064s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020856,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":693,"lbm_read_time_us":15979,"lbm_reads_lt_1ms":771,"lbm_write_time_us":29565,"lbm_writes_lt_1ms":743,"mutex_wait_us":85,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:18:48.847821  8791 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.848229  8791 tablet_replica.cc:333] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7: stopping tablet replica
I20260812 06:18:48.848464  8791 raft_consensus.cc:2243] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.848711  8791 raft_consensus.cc:2272] T 300a786033724ca59d8b0e5e1b53cabe P 0056747ea1b1440a88d3528fea7a8bb7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.864910  8791 tablet_server.cc:196] TabletServer@127.8.149.193:0 shutdown complete.
I20260812 06:18:48.904718  8791 master.cc:562] Master@127.8.149.254:39417 shutting down...
I20260812 06:18:48.908200  8791 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.908377  8791 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.908463  8791 tablet_replica.cc:333] T 00000000000000000000000000000000 P 28f18da6f86b451cabf24a40669e17af: stopping tablet replica
I20260812 06:18:48.920770  8791 master.cc:584] Master@127.8.149.254:39417 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5068 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:49.003158  8791 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.149.254:42427
I20260812 06:18:49.004844  8791 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:49.006991  9133 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:49.007025  9131 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:49.007184  9135 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:49.007153  8791 server_base.cc:1061] running on GCE node
I20260812 06:18:49.007550  8791 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:49.007598  8791 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:49.007613  8791 hybrid_clock.cc:648] HybridClock initialized: now 1786515529007613 us; error 0 us; skew 500 ppm
I20260812 06:18:49.008462  8791 webserver.cc:533] Webserver started at http://127.8.149.254:43317/ using document root <none> and password file <none>
I20260812 06:18:49.008620  8791 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:49.008670  8791 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:49.008750  8791 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:49.009256  8791 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/master-0-root/instance:
uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-21b9"
I20260812 06:18:49.010775  8791 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:49.011768  9150 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:49.011981  8791 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:49.012048  8791 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/master-0-root
uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-21b9"
I20260812 06:18:49.012104  8791 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-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:49.032354  8791 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:49.032758  8791 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:49.036988  8791 rpc_server.cc:307] RPC server started. Bound to: 127.8.149.254:42427
I20260812 06:18:49.040452  9239 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.149.254:42427 every 8 connection(s)
I20260812 06:18:49.040970  9240 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:49.042855  9240 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c: Bootstrap starting.
I20260812 06:18:49.043697  9240 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:49.044759  9240 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c: No bootstrap required, opened a new log
I20260812 06:18:49.045151  9240 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER }
I20260812 06:18:49.045241  9240 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:49.045274  9240 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2feb3d5ccd8b4d1a8d0a58344fb0634c, State: Initialized, Role: FOLLOWER
I20260812 06:18:49.045413  9240 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [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: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER }
I20260812 06:18:49.045486  9240 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:49.045519  9240 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:49.045567  9240 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:49.046242  9240 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER }
I20260812 06:18:49.046371  9240 leader_election.cc:304] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [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: 2feb3d5ccd8b4d1a8d0a58344fb0634c; no voters: 
I20260812 06:18:49.046548  9240 leader_election.cc:290] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:49.046648  9244 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:49.046802  9244 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 1 LEADER]: Becoming Leader. State: Replica: 2feb3d5ccd8b4d1a8d0a58344fb0634c, State: Running, Role: LEADER
I20260812 06:18:49.046929  9244 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [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: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER }
I20260812 06:18:49.047009  9240 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:49.047341  9247 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2feb3d5ccd8b4d1a8d0a58344fb0634c. Latest consensus state: current_term: 1 leader_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER } }
I20260812 06:18:49.047437  9247 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:49.047400  9245 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feb3d5ccd8b4d1a8d0a58344fb0634c" member_type: VOTER } }
I20260812 06:18:49.047705  9245 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:49.048134  9250 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:49.048977  9250 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:49.049197  8791 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:49.050839  9250 catalog_manager.cc:1383] Generated new cluster ID: 7de2de8ce41245638ae75fd151767fbf
I20260812 06:18:49.050895  9250 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:49.076346  9250 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:49.076941  9250 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:49.089805  9250 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c: Generated new TSK 0
I20260812 06:18:49.089999  9250 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:49.113734  8791 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:49.115706  9274 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:49.115763  9275 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:49.115896  8791 server_base.cc:1061] running on GCE node
W20260812 06:18:49.115996  9277 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:49.116302  8791 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:49.116361  8791 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:49.116400  8791 hybrid_clock.cc:648] HybridClock initialized: now 1786515529116400 us; error 0 us; skew 500 ppm
I20260812 06:18:49.117381  8791 webserver.cc:533] Webserver started at http://127.8.149.193:39839/ using document root <none> and password file <none>
I20260812 06:18:49.117558  8791 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:49.117620  8791 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:49.117715  8791 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:49.118149  8791 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/instance:
uuid: "b1b8c15fe1b54954bc765ab35b2f98d4"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-21b9"
I20260812 06:18:49.119774  8791 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:49.120723  9289 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:49.120965  8791 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:49.121035  8791 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root
uuid: "b1b8c15fe1b54954bc765ab35b2f98d4"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-21b9"
I20260812 06:18:49.121102  8791 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-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:49.129667  8791 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:49.130007  8791 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:49.130282  8791 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:49.130712  8791 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:49.130749  8791 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.130793  8791 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:49.130820  8791 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.134884  8791 rpc_server.cc:307] RPC server started. Bound to: 127.8.149.193:39549
I20260812 06:18:49.136349  9405 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.149.193:39549 every 8 connection(s)
I20260812 06:18:49.143846  9406 heartbeater.cc:344] Connected to a master server at 127.8.149.254:42427
I20260812 06:18:49.143954  9406 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:49.144188  9406 heartbeater.cc:507] Master 127.8.149.254:42427 requested a full tablet report, sending...
I20260812 06:18:49.144857  9178 ts_manager.cc:194] Registered new tserver with Master: b1b8c15fe1b54954bc765ab35b2f98d4 (127.8.149.193:39549)
I20260812 06:18:49.145370  8791 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009912517s
I20260812 06:18:49.145632  9178 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49058
I20260812 06:18:49.151954  9178 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49060:
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:49.160275  9345 tablet_service.cc:1511] Processing CreateTablet for tablet c08d5d9cbb634ba68b48f06cf6b96e71 (DEFAULT_TABLE table=heavy-update-compaction-test [id=461e681f50264a28aa019a67df34c71b]), partition=
I20260812 06:18:49.160521  9345 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c08d5d9cbb634ba68b48f06cf6b96e71. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:49.162348  9431 tablet_bootstrap.cc:492] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Bootstrap starting.
I20260812 06:18:49.163208  9431 tablet_bootstrap.cc:654] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:49.164237  9431 tablet_bootstrap.cc:492] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: No bootstrap required, opened a new log
I20260812 06:18:49.164310  9431 ts_tablet_manager.cc:1403] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:49.164682  9431 raft_consensus.cc:359] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1b8c15fe1b54954bc765ab35b2f98d4" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 39549 } }
I20260812 06:18:49.164789  9431 raft_consensus.cc:385] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:49.164830  9431 raft_consensus.cc:740] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b1b8c15fe1b54954bc765ab35b2f98d4, State: Initialized, Role: FOLLOWER
I20260812 06:18:49.164969  9431 consensus_queue.cc:260] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [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: "b1b8c15fe1b54954bc765ab35b2f98d4" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 39549 } }
I20260812 06:18:49.165064  9431 raft_consensus.cc:399] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:49.165109  9431 raft_consensus.cc:493] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:49.165162  9431 raft_consensus.cc:3060] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:49.165870  9431 raft_consensus.cc:515] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1b8c15fe1b54954bc765ab35b2f98d4" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 39549 } }
I20260812 06:18:49.166002  9431 leader_election.cc:304] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [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: b1b8c15fe1b54954bc765ab35b2f98d4; no voters: 
I20260812 06:18:49.166191  9431 leader_election.cc:290] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:49.166293  9436 raft_consensus.cc:2804] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:49.166494  9436 raft_consensus.cc:697] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 1 LEADER]: Becoming Leader. State: Replica: b1b8c15fe1b54954bc765ab35b2f98d4, State: Running, Role: LEADER
I20260812 06:18:49.166503  9431 ts_tablet_manager.cc:1434] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:49.166518  9406 heartbeater.cc:499] Master 127.8.149.254:42427 was elected leader, sending a full tablet report...
I20260812 06:18:49.166649  9436 consensus_queue.cc:237] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [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: "b1b8c15fe1b54954bc765ab35b2f98d4" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 39549 } }
I20260812 06:18:49.167920  9178 catalog_manager.cc:5719] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 reported cstate change: term changed from 0 to 1, leader changed from <none> to b1b8c15fe1b54954bc765ab35b2f98d4 (127.8.149.193). New cstate: current_term: 1 leader_uuid: "b1b8c15fe1b54954bc765ab35b2f98d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1b8c15fe1b54954bc765ab35b2f98d4" member_type: VOTER last_known_addr { host: "127.8.149.193" port: 39549 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:49.224396  8791 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.022s	sys 0.000s
I20260812 06:18:49.386873  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=23.023690
I20260812 06:18:49.561796  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.175s	user 0.125s	sys 0.047s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":698,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44971,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:49.562471  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): free 20743880 bytes of WAL
I20260812 06:18:49.562729  9296 log_reader.cc:385] T c08d5d9cbb634ba68b48f06cf6b96e71: removed 2 log segments from log reader
I20260812 06:18:49.562798  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000001 (ops 1-6)
I20260812 06:18:49.562839  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000002 (ops 7-11)
I20260812 06:18:49.567634  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:49.568082  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): 20513814 bytes on disk
I20260812 06:18:49.568531  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.568943  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=3.181125
I20260812 06:18:49.583009  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:49.583489  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:49.739252  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.156s	user 0.112s	sys 0.038s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21123514,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":542,"lbm_read_time_us":11460,"lbm_reads_lt_1ms":470,"lbm_write_time_us":25117,"lbm_writes_lt_1ms":453,"mutex_wait_us":38,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":328,"threads_started":5,"update_count":2050}
I20260812 06:18:49.739810  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:49.797606  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.058s	user 0.027s	sys 0.021s Metrics: {"bytes_written":15999660,"delete_count":0,"lbm_write_time_us":18225,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:18:49.798190  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:49.808542  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.809026  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:49.980432  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.171s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405442,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":585,"lbm_read_time_us":11804,"lbm_reads_lt_1ms":562,"lbm_write_time_us":27678,"lbm_writes_lt_1ms":533,"mutex_wait_us":243,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2450}
I20260812 06:18:49.980932  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=11.118625
I20260812 06:18:50.026535  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.045s	user 0.036s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19087,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:50.027190  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.057000  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.029s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.057572  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.067258  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.067818  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:50.244961  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.177s	user 0.101s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":111,"lbm_read_time_us":11616,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27238,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:18:50.245534  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:50.297333  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.052s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20073,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.297863  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.313319  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.313817  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:50.497682  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.184s	user 0.129s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"lbm_read_time_us":13058,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27304,"lbm_writes_lt_1ms":543,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2500}
I20260812 06:18:50.498267  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:50.544807  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.046s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18320,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.545289  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.560863  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.561443  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:50.712558  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.151s	user 0.106s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":8447,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29479,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:50.713235  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:50.750968  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.751518  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.762354  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.762914  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:50.788887  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.026s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1480,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1366,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:50.789531  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): free 112239306 bytes of WAL
I20260812 06:18:50.789757  9296 log_reader.cc:385] T c08d5d9cbb634ba68b48f06cf6b96e71: removed 11 log segments from log reader
I20260812 06:18:50.789809  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000003 (ops 12-16)
I20260812 06:18:50.789851  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000004 (ops 17-20)
I20260812 06:18:50.789881  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000005 (ops 21-25)
I20260812 06:18:50.789915  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000006 (ops 26-30)
I20260812 06:18:50.789947  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000007 (ops 31-35)
I20260812 06:18:50.789975  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000008 (ops 36-40)
I20260812 06:18:50.790004  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000009 (ops 41-45)
I20260812 06:18:50.790032  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000010 (ops 46-50)
I20260812 06:18:50.790066  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000011 (ops 51-55)
I20260812 06:18:50.790098  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000012 (ops 56-60)
I20260812 06:18:50.790125  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000013 (ops 61-65)
I20260812 06:18:50.813665  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:50.814105  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=3.181125
I20260812 06:18:50.830669  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.831146  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): 447 bytes on disk
I20260812 06:18:50.831616  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) 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:50.832084  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:50.846351  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4835,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.846956  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:51.050704  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.203s	user 0.131s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":763,"lbm_read_time_us":12075,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33554,"lbm_writes_lt_1ms":643,"mutex_wait_us":123,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:51.051697  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:51.092098  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.040s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17334,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.092650  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:51.116813  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.024s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.117506  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:51.276086  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.158s	user 0.107s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":10785,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25019,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:51.276721  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:51.317735  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17585,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.318185  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:51.329797  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.330205  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:51.494081  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.164s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":10566,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28971,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:18:51.494658  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:51.543220  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.048s	user 0.038s	sys 0.003s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.543674  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:51.553741  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.554374  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:51.679374  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.125s	user 0.106s	sys 0.018s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":855,"lbm_read_time_us":8109,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24331,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:51.679983  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:51.708050  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.028s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11979,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:51.708578  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:51.720198  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.720762  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:51.847487  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.127s	user 0.099s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":8155,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24074,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:51.848089  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:51.890132  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.042s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15171,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.890703  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:51.900384  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.900821  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.017504  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.117s	user 0.105s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":185,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20778,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:18:52.018097  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:52.068606  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.050s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14092,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.069178  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:52.079669  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.080102  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.109241  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1248,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1266,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:52.110013  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.258740  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.149s	user 0.090s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":8575,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22680,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:18:52.259298  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): free 121006437 bytes of WAL
I20260812 06:18:52.259699  9296 log_reader.cc:385] T c08d5d9cbb634ba68b48f06cf6b96e71: removed 12 log segments from log reader
I20260812 06:18:52.259748  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000014 (ops 66-70)
I20260812 06:18:52.259788  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000015 (ops 71-74)
I20260812 06:18:52.259846  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000016 (ops 75-79)
I20260812 06:18:52.259883  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000017 (ops 80-84)
I20260812 06:18:52.259943  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000018 (ops 85-89)
I20260812 06:18:52.259986  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000019 (ops 90-94)
I20260812 06:18:52.260040  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000020 (ops 95-99)
I20260812 06:18:52.260074  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000021 (ops 100-104)
I20260812 06:18:52.260128  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000022 (ops 105-109)
I20260812 06:18:52.260161  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000023 (ops 110-114)
I20260812 06:18:52.260214  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000024 (ops 115-119)
I20260812 06:18:52.260248  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000025 (ops 120-124)
I20260812 06:18:52.284202  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:52.284623  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): 462 bytes on disk
I20260812 06:18:52.285092  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.285640  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=15.087375
I20260812 06:18:52.334091  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.048s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":20623,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:52.334537  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:52.345724  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.346180  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:52.363138  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.017s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3385,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.363643  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.554749  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.191s	user 0.124s	sys 0.066s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":197,"lbm_read_time_us":13607,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31018,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:52.555303  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:52.610333  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.055s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":16332,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.610939  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:52.621449  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.621901  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.787834  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.166s	user 0.110s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":12062,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26709,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:18:52.788353  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:52.819814  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.031s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13077,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.820448  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:52.839998  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.840515  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:52.961087  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.120s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":8643,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21670,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:52.961576  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:52.994038  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.032s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14611,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.994513  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.012718  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.018s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.013185  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.130460  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.117s	user 0.093s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":944,"lbm_read_time_us":7825,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21684,"lbm_writes_lt_1ms":443,"mutex_wait_us":678,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:53.131114  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:53.169174  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.038s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.169780  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.185154  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.185794  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.309940  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":509,"lbm_read_time_us":9373,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22093,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:18:53.310528  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:53.355861  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.045s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.356403  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.366411  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.366827  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.498237  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.131s	user 0.083s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":9936,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20273,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:53.498785  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=10.126437
I20260812 06:18:53.539772  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.041s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13749,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.540405  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.556222  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.556854  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.585109  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushMRSOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.028s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1322,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1393,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:53.585963  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): free 133024628 bytes of WAL
I20260812 06:18:53.586230  9296 log_reader.cc:385] T c08d5d9cbb634ba68b48f06cf6b96e71: removed 13 log segments from log reader
I20260812 06:18:53.586295  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000026 (ops 125-129)
I20260812 06:18:53.586334  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000027 (ops 130-134)
I20260812 06:18:53.586364  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000028 (ops 135-139)
I20260812 06:18:53.586386  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000029 (ops 140-144)
I20260812 06:18:53.586426  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000030 (ops 145-149)
I20260812 06:18:53.586458  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000031 (ops 150-154)
I20260812 06:18:53.586484  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000032 (ops 155-159)
I20260812 06:18:53.586512  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000033 (ops 160-164)
I20260812 06:18:53.586540  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000034 (ops 165-168)
I20260812 06:18:53.586570  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000035 (ops 169-173)
I20260812 06:18:53.586599  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000036 (ops 174-178)
I20260812 06:18:53.586627  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000037 (ops 179-183)
I20260812 06:18:53.586652  9296 log.cc:1079] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: Deleting log segment in path: /tmp/dist-test-taskwT2mgP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523911473-8791-0/minicluster-data/ts-0-root/wals/c08d5d9cbb634ba68b48f06cf6b96e71/wal-000000038 (ops 184-188)
I20260812 06:18:53.613920  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: LogGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:53.614360  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=3.181125
I20260812 06:18:53.632061  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6707,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:53.632540  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.649574  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3253,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.650283  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.842352  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.192s	user 0.139s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1280,"lbm_read_time_us":13203,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29925,"lbm_writes_lt_1ms":643,"mutex_wait_us":423,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8320,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:53.842869  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71): 482 bytes on disk
I20260812 06:18:53.843321  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: UndoDeltaBlockGCOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.843920  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=14.095187
I20260812 06:18:53.890729  8791 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.666s	user 1.691s	sys 0.168s
I20260812 06:18:53.901371  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.057s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17019,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.901854  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=2.188937
I20260812 06:18:53.911535  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: FlushDeltaMemStoresOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:18:53.911935  9411 maintenance_manager.cc:419] P b1b8c15fe1b54954bc765ab35b2f98d4: Scheduling MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71): perf score=1.000000
I20260812 06:18:53.967389  8791 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.004s	sys 0.000s
I20260812 06:18:53.968055  8791 tablet_server.cc:179] TabletServer@127.8.149.193:0 shutting down...
I20260812 06:18:54.043081  9296 maintenance_manager.cc:643] P b1b8c15fe1b54954bc765ab35b2f98d4: MajorDeltaCompactionOp(c08d5d9cbb634ba68b48f06cf6b96e71) complete. Timing: real 0.131s	user 0.096s	sys 0.035s Metrics: {"cfile_cache_hit":267,"cfile_cache_hit_bytes":10914293,"cfile_cache_miss":265,"cfile_cache_miss_bytes":13901389,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":389,"lbm_read_time_us":6756,"lbm_reads_lt_1ms":297,"lbm_write_time_us":24003,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":68096,"update_count":2500}
I20260812 06:18:54.044026  8791 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:54.044248  8791 tablet_replica.cc:333] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4: stopping tablet replica
I20260812 06:18:54.044373  8791 raft_consensus.cc:2243] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:54.044548  8791 raft_consensus.cc:2272] T c08d5d9cbb634ba68b48f06cf6b96e71 P b1b8c15fe1b54954bc765ab35b2f98d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:54.048791  8791 tablet_server.cc:196] TabletServer@127.8.149.193:0 shutdown complete.
I20260812 06:18:54.088579  8791 master.cc:562] Master@127.8.149.254:42427 shutting down...
I20260812 06:18:54.091550  8791 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:54.091722  8791 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:54.091792  8791 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2feb3d5ccd8b4d1a8d0a58344fb0634c: stopping tablet replica
I20260812 06:18:54.104033  8791 master.cc:584] Master@127.8.149.254:42427 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5184 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10254 ms total)

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