[==========] 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:19:38.969965  1613 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.147.126:37841
I20260812 06:19:38.971045  1613 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:19:38.971669  1613 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:38.978184  1619 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:19:38.978252  1613 server_base.cc:1061] running on GCE node
W20260812 06:19:38.978173  1618 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:19:38.978415  1621 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:19:38.978911  1613 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:38.979003  1613 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:19:38.979038  1613 hybrid_clock.cc:648] HybridClock initialized: now 1786515578979036 us; error 0 us; skew 500 ppm
I20260812 06:19:38.980749  1613 webserver.cc:533] Webserver started at http://127.1.147.126:34491/ using document root <none> and password file <none>
I20260812 06:19:38.981266  1613 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:38.981321  1613 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:38.981513  1613 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:38.983170  1613 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/master-0-root/instance:
uuid: "308ef0c4175746b99e96d4d0a1e69a88"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-pgkr"
I20260812 06:19:38.986577  1613 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:38.988716  1627 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:19:38.989797  1613 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:38.989904  1613 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/master-0-root
uuid: "308ef0c4175746b99e96d4d0a1e69a88"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-pgkr"
I20260812 06:19:38.989992  1613 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-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:19:39.034152  1613 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.034911  1613 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:19:39.035063  1613 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.042932  1613 rpc_server.cc:307] RPC server started. Bound to: 127.1.147.126:37841
I20260812 06:19:39.043054  1682 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.147.126:37841 every 8 connection(s)
I20260812 06:19:39.045535  1683 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:19:39.051460  1683 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: Bootstrap starting.
I20260812 06:19:39.053845  1683 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.054836  1683 log.cc:826] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:39.056582  1683 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: No bootstrap required, opened a new log
I20260812 06:19:39.059449  1683 raft_consensus.cc:359] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER }
I20260812 06:19:39.059629  1683 raft_consensus.cc:385] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.059674  1683 raft_consensus.cc:740] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 308ef0c4175746b99e96d4d0a1e69a88, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.060389  1683 consensus_queue.cc:260] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [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: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER }
I20260812 06:19:39.060534  1683 raft_consensus.cc:399] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.060633  1683 raft_consensus.cc:493] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.060793  1683 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.061597  1683 raft_consensus.cc:515] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER }
I20260812 06:19:39.062047  1683 leader_election.cc:304] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [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: 308ef0c4175746b99e96d4d0a1e69a88; no voters: 
I20260812 06:19:39.062379  1683 leader_election.cc:290] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.062565  1686 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.062885  1686 raft_consensus.cc:697] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 1 LEADER]: Becoming Leader. State: Replica: 308ef0c4175746b99e96d4d0a1e69a88, State: Running, Role: LEADER
I20260812 06:19:39.063258  1686 consensus_queue.cc:237] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [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: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER }
I20260812 06:19:39.063473  1683 sys_catalog.cc:565] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:39.065276  1687 sys_catalog.cc:455] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "308ef0c4175746b99e96d4d0a1e69a88" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER } }
I20260812 06:19:39.065331  1688 sys_catalog.cc:455] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 308ef0c4175746b99e96d4d0a1e69a88. Latest consensus state: current_term: 1 leader_uuid: "308ef0c4175746b99e96d4d0a1e69a88" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "308ef0c4175746b99e96d4d0a1e69a88" member_type: VOTER } }
I20260812 06:19:39.065404  1687 sys_catalog.cc:458] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.065423  1688 sys_catalog.cc:458] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.065779  1697 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:39.068131  1697 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:39.068490  1613 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:39.072937  1697 catalog_manager.cc:1383] Generated new cluster ID: 59f8cd8f15a04e4885b84204dbfcf6e0
I20260812 06:19:39.073009  1697 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:39.081338  1697 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:39.082397  1697 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:39.096987  1697 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: Generated new TSK 0
I20260812 06:19:39.097776  1697 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:39.101007  1613 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.103979  1709 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:19:39.104085  1711 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:19:39.103965  1713 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:19:39.104739  1613 server_base.cc:1061] running on GCE node
I20260812 06:19:39.104961  1613 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.105018  1613 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:19:39.105036  1613 hybrid_clock.cc:648] HybridClock initialized: now 1786515579105036 us; error 0 us; skew 500 ppm
I20260812 06:19:39.106062  1613 webserver.cc:533] Webserver started at http://127.1.147.65:37937/ using document root <none> and password file <none>
I20260812 06:19:39.106243  1613 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.106292  1613 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.106390  1613 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.106873  1613 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/instance:
uuid: "4681680640b646719f457130bea18602"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-pgkr"
I20260812 06:19:39.108409  1613 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:39.109417  1718 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:19:39.109666  1613 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:39.109740  1613 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root
uuid: "4681680640b646719f457130bea18602"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-pgkr"
I20260812 06:19:39.109827  1613 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-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:19:39.123804  1613 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.124464  1613 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.125046  1613 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:39.126053  1613 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:39.126134  1613 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.126231  1613 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:39.126278  1613 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.134022  1613 rpc_server.cc:307] RPC server started. Bound to: 127.1.147.65:36855
I20260812 06:19:39.134053  1791 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.147.65:36855 every 8 connection(s)
I20260812 06:19:39.144321  1792 heartbeater.cc:344] Connected to a master server at 127.1.147.126:37841
I20260812 06:19:39.144601  1792 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:39.145119  1792 heartbeater.cc:507] Master 127.1.147.126:37841 requested a full tablet report, sending...
I20260812 06:19:39.146760  1645 ts_manager.cc:194] Registered new tserver with Master: 4681680640b646719f457130bea18602 (127.1.147.65:36855)
I20260812 06:19:39.147149  1613 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012311477s
I20260812 06:19:39.148305  1645 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51572
I20260812 06:19:39.156775  1645 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51574:
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:19:39.173039  1753 tablet_service.cc:1511] Processing CreateTablet for tablet 9b7939d03d074d78a2525412d62ebbe7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=abb764ef7bfa4a06bbf060acb175f6b9]), partition=
I20260812 06:19:39.173563  1753 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9b7939d03d074d78a2525412d62ebbe7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.176164  1804 tablet_bootstrap.cc:492] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Bootstrap starting.
I20260812 06:19:39.177325  1804 tablet_bootstrap.cc:654] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.178696  1804 tablet_bootstrap.cc:492] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: No bootstrap required, opened a new log
I20260812 06:19:39.178808  1804 ts_tablet_manager.cc:1403] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:39.179334  1804 raft_consensus.cc:359] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4681680640b646719f457130bea18602" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 36855 } }
I20260812 06:19:39.179461  1804 raft_consensus.cc:385] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.179497  1804 raft_consensus.cc:740] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4681680640b646719f457130bea18602, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.179677  1804 consensus_queue.cc:260] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [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: "4681680640b646719f457130bea18602" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 36855 } }
I20260812 06:19:39.179780  1804 raft_consensus.cc:399] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.179865  1804 raft_consensus.cc:493] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.179924  1804 raft_consensus.cc:3060] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.180931  1804 raft_consensus.cc:515] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4681680640b646719f457130bea18602" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 36855 } }
I20260812 06:19:39.181087  1804 leader_election.cc:304] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [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: 4681680640b646719f457130bea18602; no voters: 
I20260812 06:19:39.181284  1804 leader_election.cc:290] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.181433  1806 raft_consensus.cc:2804] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.181694  1806 raft_consensus.cc:697] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 1 LEADER]: Becoming Leader. State: Replica: 4681680640b646719f457130bea18602, State: Running, Role: LEADER
I20260812 06:19:39.181712  1804 ts_tablet_manager.cc:1434] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:39.181950  1792 heartbeater.cc:499] Master 127.1.147.126:37841 was elected leader, sending a full tablet report...
I20260812 06:19:39.182103  1806 consensus_queue.cc:237] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [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: "4681680640b646719f457130bea18602" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 36855 } }
I20260812 06:19:39.185223  1645 catalog_manager.cc:5719] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4681680640b646719f457130bea18602 (127.1.147.65). New cstate: current_term: 1 leader_uuid: "4681680640b646719f457130bea18602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4681680640b646719f457130bea18602" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 36855 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:39.266088  1613 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.073s	user 0.021s	sys 0.012s
I20260812 06:19:39.385244  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7): perf score=15.086190
I20260812 06:19:39.561825  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.176s	user 0.127s	sys 0.035s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":293,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1090,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41469,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":1408,"thread_start_us":136,"threads_started":1,"update_count":1500}
I20260812 06:19:39.563095  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling LogGCOp(9b7939d03d074d78a2525412d62ebbe7): free 11976772 bytes of WAL
I20260812 06:19:39.563403  1725 log_reader.cc:385] T 9b7939d03d074d78a2525412d62ebbe7: removed 1 log segments from log reader
I20260812 06:19:39.563465  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000001 (ops 1-6)
I20260812 06:19:39.566985  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: LogGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:39.567337  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7): 12308958 bytes on disk
I20260812 06:19:39.567925  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.568331  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:39.586980  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5435,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.587575  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:39.731755  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.144s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":8752,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26138,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":308,"threads_started":5,"update_count":2000}
I20260812 06:19:39.732520  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:39.771365  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16738,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.771859  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:39.787312  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.015s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.787993  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:39.904181  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.116s	user 0.073s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":7826,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23302,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:19:39.904824  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:39.953012  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.048s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23910,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.953549  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:39.966004  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.966439  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.092716  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.126s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":7745,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25793,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":67968,"update_count":2000}
I20260812 06:19:40.093317  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:40.143481  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.050s	user 0.018s	sys 0.030s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18925,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.144068  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:40.155452  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.155979  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.302832  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.147s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":10949,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24919,"lbm_writes_lt_1ms":443,"mutex_wait_us":17,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:19:40.303515  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:40.349058  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.045s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18806,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.349520  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:40.360661  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.361339  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.491098  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.130s	user 0.098s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":9423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26664,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2000}
I20260812 06:19:40.491813  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:40.533937  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.042s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17803,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.534475  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:40.545253  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.545817  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.679040  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.133s	user 0.108s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":9760,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27448,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":85760,"update_count":2000}
I20260812 06:19:40.679718  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=10.126437
I20260812 06:19:40.729353  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.049s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.729933  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:40.742800  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.743294  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.773360  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1253,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:40.774266  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling LogGCOp(9b7939d03d074d78a2525412d62ebbe7): free 121006371 bytes of WAL
I20260812 06:19:40.774533  1725 log_reader.cc:385] T 9b7939d03d074d78a2525412d62ebbe7: removed 12 log segments from log reader
I20260812 06:19:40.774600  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000002 (ops 7-11)
I20260812 06:19:40.774685  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000003 (ops 12-16)
I20260812 06:19:40.774753  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000004 (ops 17-21)
I20260812 06:19:40.774801  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000005 (ops 22-26)
I20260812 06:19:40.774845  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000006 (ops 27-30)
I20260812 06:19:40.774893  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000007 (ops 31-35)
I20260812 06:19:40.774935  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000008 (ops 36-40)
I20260812 06:19:40.774977  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000009 (ops 41-45)
I20260812 06:19:40.775029  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000010 (ops 46-50)
I20260812 06:19:40.775071  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000011 (ops 51-55)
I20260812 06:19:40.775113  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000012 (ops 56-60)
I20260812 06:19:40.775156  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000013 (ops 61-65)
I20260812 06:19:40.804085  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: LogGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.030s	user 0.002s	sys 0.026s Metrics: {}
I20260812 06:19:40.804589  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=6.157687
I20260812 06:19:40.824052  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":7917910,"delete_count":0,"lbm_write_time_us":7935,"lbm_writes_lt_1ms":196,"reinsert_count":0,"update_count":965}
I20260812 06:19:40.824692  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7): 448 bytes on disk
I20260812 06:19:40.825145  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.825881  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:40.993158  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.167s	user 0.135s	sys 0.028s Metrics: {"cfile_cache_miss":626,"cfile_cache_miss_bytes":28549088,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":160,"lbm_read_time_us":12245,"lbm_reads_lt_1ms":662,"lbm_write_time_us":32720,"lbm_writes_lt_1ms":636,"mutex_wait_us":47,"peak_mem_usage":74214843,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":93,"threads_started":1,"update_count":2965}
I20260812 06:19:40.995733  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=15.087375
I20260812 06:19:41.047876  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.052s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16697073,"delete_count":0,"lbm_write_time_us":24279,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2035}
I20260812 06:19:41.048425  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:41.064661  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.065212  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:41.208323  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.143s	user 0.069s	sys 0.074s Metrics: {"cfile_cache_miss":539,"cfile_cache_miss_bytes":25020894,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":909,"lbm_read_time_us":11038,"lbm_reads_lt_1ms":579,"lbm_write_time_us":28700,"lbm_writes_lt_1ms":550,"mutex_wait_us":24,"peak_mem_usage":63403145,"reinsert_count":0,"update_count":2535}
I20260812 06:19:41.208921  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:41.269526  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.060s	user 0.019s	sys 0.026s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21201,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.270048  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:41.281776  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.282289  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:41.446420  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.164s	user 0.126s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":9757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32093,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34304,"update_count":2500}
I20260812 06:19:41.447296  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=12.110812
I20260812 06:19:41.482419  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.035s	user 0.024s	sys 0.008s Metrics: {"bytes_written":13661279,"delete_count":0,"lbm_write_time_us":15180,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:19:41.483115  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.196750
I20260812 06:19:41.496570  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:41.497095  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:41.648351  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.151s	user 0.112s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":11183,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25196,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:19:41.648945  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:41.702282  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.053s	user 0.016s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.702935  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:41.722227  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.722796  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:41.919809  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.197s	user 0.147s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1378,"lbm_read_time_us":13266,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34120,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:41.920624  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:41.975682  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.055s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22362,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.976233  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:41.987006  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.987483  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:42.149432  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.162s	user 0.103s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":68,"lbm_read_time_us":9787,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29241,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:19:42.150439  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=11.118625
I20260812 06:19:42.181015  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.030s	user 0.007s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13130,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:42.181761  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:42.196488  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5090,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.197167  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:42.234428  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.037s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1267,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1645,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:42.236101  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7): 482 bytes on disk
I20260812 06:19:42.236578  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.237044  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=3.181125
I20260812 06:19:42.248672  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:42.249168  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling LogGCOp(9b7939d03d074d78a2525412d62ebbe7): free 124257314 bytes of WAL
I20260812 06:19:42.249416  1725 log_reader.cc:385] T 9b7939d03d074d78a2525412d62ebbe7: removed 12 log segments from log reader
I20260812 06:19:42.249475  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000014 (ops 66-70)
I20260812 06:19:42.249523  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000015 (ops 71-75)
I20260812 06:19:42.249554  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000016 (ops 76-80)
I20260812 06:19:42.249583  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000017 (ops 81-85)
I20260812 06:19:42.249619  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000018 (ops 86-90)
I20260812 06:19:42.249650  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000019 (ops 91-95)
I20260812 06:19:42.249679  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000020 (ops 96-100)
I20260812 06:19:42.249707  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000021 (ops 101-104)
I20260812 06:19:42.249735  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000022 (ops 105-109)
I20260812 06:19:42.249769  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000023 (ops 110-114)
I20260812 06:19:42.249801  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000024 (ops 115-119)
I20260812 06:19:42.249830  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000025 (ops 120-124)
I20260812 06:19:42.279304  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: LogGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:42.279927  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:42.296103  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.016s	user 0.010s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.296631  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:42.493034  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.196s	user 0.115s	sys 0.081s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836350,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":429,"lbm_read_time_us":14600,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35242,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:19:42.493705  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=15.087375
I20260812 06:19:42.546278  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16574001,"delete_count":0,"lbm_write_time_us":18172,"lbm_writes_lt_1ms":407,"reinsert_count":0,"update_count":2020}
I20260812 06:19:42.546752  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=3.181125
I20260812 06:19:42.563418  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.017s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":4925,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:19:42.563861  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:42.746691  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.183s	user 0.131s	sys 0.051s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25143971,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":451,"lbm_read_time_us":11915,"lbm_reads_lt_1ms":574,"lbm_write_time_us":31514,"lbm_writes_lt_1ms":553,"mutex_wait_us":32,"peak_mem_usage":63526250,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2550}
I20260812 06:19:42.747422  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:42.798086  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":15999662,"delete_count":0,"lbm_write_time_us":21959,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:19:42.798593  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:42.825645  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.027s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.826282  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:42.989554  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.163s	user 0.124s	sys 0.038s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24323483,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":504,"lbm_read_time_us":12268,"lbm_reads_lt_1ms":554,"lbm_write_time_us":27436,"lbm_writes_lt_1ms":533,"mutex_wait_us":20,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2450}
I20260812 06:19:42.990190  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:43.049508  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.059s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27020,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.049995  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:43.061322  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.061789  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:43.231428  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.169s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":891,"lbm_read_time_us":10930,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30048,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:19:43.232183  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:43.284152  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.052s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21564,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.284725  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:43.299741  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.300313  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:43.469936  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.169s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":897,"lbm_read_time_us":10952,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35564,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:19:43.470440  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:43.526257  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.056s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23561,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.526955  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:43.543406  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.544080  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:43.698792  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.154s	user 0.127s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":11920,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29950,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:19:43.699440  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:43.747555  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.048s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18942,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.748049  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:43.760346  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.761053  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:43.789261  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushMRSOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1996,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1408}
I20260812 06:19:43.789983  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling LogGCOp(9b7939d03d074d78a2525412d62ebbe7): free 129320714 bytes of WAL
I20260812 06:19:43.790246  1725 log_reader.cc:385] T 9b7939d03d074d78a2525412d62ebbe7: removed 13 log segments from log reader
I20260812 06:19:43.790311  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000026 (ops 125-129)
I20260812 06:19:43.790365  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000027 (ops 130-134)
I20260812 06:19:43.790416  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000028 (ops 135-139)
I20260812 06:19:43.790458  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000029 (ops 140-144)
I20260812 06:19:43.790495  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000030 (ops 145-148)
I20260812 06:19:43.790540  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000031 (ops 149-153)
I20260812 06:19:43.790581  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000032 (ops 154-158)
I20260812 06:19:43.790637  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000033 (ops 159-162)
I20260812 06:19:43.790683  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000034 (ops 163-167)
I20260812 06:19:43.790717  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000035 (ops 168-172)
I20260812 06:19:43.790752  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000036 (ops 173-177)
I20260812 06:19:43.790791  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000037 (ops 178-182)
I20260812 06:19:43.790835  1725 log.cc:1079] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/9b7939d03d074d78a2525412d62ebbe7/wal-000000038 (ops 183-187)
I20260812 06:19:43.820622  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: LogGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:19:43.821234  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7): 483 bytes on disk
I20260812 06:19:43.821668  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: UndoDeltaBlockGCOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.822284  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=4.173312
I20260812 06:19:43.837898  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.015s	user 0.002s	sys 0.011s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":6334,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:19:43.838409  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.196750
I20260812 06:19:43.850454  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:43.851080  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7): perf score=1.000000
I20260812 06:19:44.048401  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: MajorDeltaCompactionOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.197s	user 0.170s	sys 0.026s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1472,"lbm_read_time_us":12995,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42276,"lbm_writes_lt_1ms":743,"mutex_wait_us":1861,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:44.049221  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=14.095187
I20260812 06:19:44.073350  1613 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.807s	user 1.818s	sys 0.077s
I20260812 06:19:44.109489  1613 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:19:44.110121  1613 tablet_server.cc:179] TabletServer@127.1.147.65:0 shutting down...
I20260812 06:19:44.114784  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.065s	user 0.041s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":27897,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:44.115439  1793 maintenance_manager.cc:419] P 4681680640b646719f457130bea18602: Scheduling FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7): perf score=2.188937
I20260812 06:19:44.127148  1725 maintenance_manager.cc:643] P 4681680640b646719f457130bea18602: FlushDeltaMemStoresOp(9b7939d03d074d78a2525412d62ebbe7) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.127751  1613 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:44.128199  1613 tablet_replica.cc:333] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602: stopping tablet replica
I20260812 06:19:44.128437  1613 raft_consensus.cc:2243] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.128680  1613 raft_consensus.cc:2272] T 9b7939d03d074d78a2525412d62ebbe7 P 4681680640b646719f457130bea18602 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.144086  1613 tablet_server.cc:196] TabletServer@127.1.147.65:0 shutdown complete.
I20260812 06:19:44.149194  1613 master.cc:562] Master@127.1.147.126:37841 shutting down...
I20260812 06:19:44.153525  1613 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.153693  1613 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.153746  1613 tablet_replica.cc:333] T 00000000000000000000000000000000 P 308ef0c4175746b99e96d4d0a1e69a88: stopping tablet replica
I20260812 06:19:44.166296  1613 master.cc:584] Master@127.1.147.126:37841 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5290 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:44.259369  1613 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.147.126:38589
I20260812 06:19:44.259758  1613 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:44.261787  1827 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:19:44.261933  1613 server_base.cc:1061] running on GCE node
W20260812 06:19:44.261848  1824 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:19:44.261906  1825 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:19:44.262143  1613 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.262202  1613 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:19:44.262228  1613 hybrid_clock.cc:648] HybridClock initialized: now 1786515584262226 us; error 0 us; skew 500 ppm
I20260812 06:19:44.263207  1613 webserver.cc:533] Webserver started at http://127.1.147.126:44185/ using document root <none> and password file <none>
I20260812 06:19:44.263381  1613 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.263446  1613 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.263525  1613 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.263913  1613 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/master-0-root/instance:
uuid: "6f0923fc02364ad498d2715b63749d18"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-pgkr"
I20260812 06:19:44.265476  1613 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:44.266384  1832 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:19:44.266700  1613 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:44.266793  1613 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/master-0-root
uuid: "6f0923fc02364ad498d2715b63749d18"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-pgkr"
I20260812 06:19:44.266882  1613 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-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:19:44.280650  1613 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.281081  1613 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.285440  1613 rpc_server.cc:307] RPC server started. Bound to: 127.1.147.126:38589
I20260812 06:19:44.297580  1898 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:19:44.304085  1897 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.147.126:38589 every 8 connection(s)
I20260812 06:19:44.305187  1898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18: Bootstrap starting.
I20260812 06:19:44.306047  1898 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.307255  1898 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18: No bootstrap required, opened a new log
I20260812 06:19:44.307687  1898 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER }
I20260812 06:19:44.307806  1898 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.307875  1898 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6f0923fc02364ad498d2715b63749d18, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.308053  1898 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [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: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER }
I20260812 06:19:44.308152  1898 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.308200  1898 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.308255  1898 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.308971  1898 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER }
I20260812 06:19:44.309135  1898 leader_election.cc:304] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [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: 6f0923fc02364ad498d2715b63749d18; no voters: 
I20260812 06:19:44.309353  1898 leader_election.cc:290] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.309499  1901 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.309731  1901 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 1 LEADER]: Becoming Leader. State: Replica: 6f0923fc02364ad498d2715b63749d18, State: Running, Role: LEADER
I20260812 06:19:44.309839  1898 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:44.309870  1901 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [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: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER }
I20260812 06:19:44.310318  1902 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6f0923fc02364ad498d2715b63749d18" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER } }
I20260812 06:19:44.310344  1903 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6f0923fc02364ad498d2715b63749d18. Latest consensus state: current_term: 1 leader_uuid: "6f0923fc02364ad498d2715b63749d18" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6f0923fc02364ad498d2715b63749d18" member_type: VOTER } }
I20260812 06:19:44.310478  1902 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.310499  1903 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.311127  1907 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:44.311888  1907 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:44.312072  1613 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:44.313827  1907 catalog_manager.cc:1383] Generated new cluster ID: e0a6575abb5541f7ab62da283baf8388
I20260812 06:19:44.313889  1907 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:44.322221  1907 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:44.322901  1907 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:44.331228  1907 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18: Generated new TSK 0
I20260812 06:19:44.331436  1907 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:44.344774  1613 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:44.346812  1922 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:19:44.346887  1613 server_base.cc:1061] running on GCE node
W20260812 06:19:44.346935  1923 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:19:44.346843  1925 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:19:44.347239  1613 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.347285  1613 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:19:44.347301  1613 hybrid_clock.cc:648] HybridClock initialized: now 1786515584347302 us; error 0 us; skew 500 ppm
I20260812 06:19:44.348104  1613 webserver.cc:533] Webserver started at http://127.1.147.65:33741/ using document root <none> and password file <none>
I20260812 06:19:44.348254  1613 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.348301  1613 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.348358  1613 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.348757  1613 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/instance:
uuid: "1ed909aad3a24e9b978d7ff7dcaccb87"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-pgkr"
I20260812 06:19:44.350302  1613 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:44.351269  1930 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:19:44.351506  1613 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:44.351570  1613 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root
uuid: "1ed909aad3a24e9b978d7ff7dcaccb87"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-pgkr"
I20260812 06:19:44.351665  1613 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-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:19:44.370347  1613 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.370818  1613 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.371151  1613 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:44.371652  1613 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:44.371690  1613 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.371754  1613 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:44.371795  1613 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.376049  1613 rpc_server.cc:307] RPC server started. Bound to: 127.1.147.65:39477
I20260812 06:19:44.376080  1999 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.147.65:39477 every 8 connection(s)
I20260812 06:19:44.384362  2000 heartbeater.cc:344] Connected to a master server at 127.1.147.126:38589
I20260812 06:19:44.384519  2000 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:44.384802  2000 heartbeater.cc:507] Master 127.1.147.126:38589 requested a full tablet report, sending...
I20260812 06:19:44.385505  1851 ts_manager.cc:194] Registered new tserver with Master: 1ed909aad3a24e9b978d7ff7dcaccb87 (127.1.147.65:39477)
I20260812 06:19:44.386206  1851 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39180
I20260812 06:19:44.386448  1613 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009939004s
I20260812 06:19:44.394188  1851 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39194:
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:19:44.403609  1960 tablet_service.cc:1511] Processing CreateTablet for tablet 17f55f266ec74a6ebd5d4ea092b7235c (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1ff535e3cd54e7fba868ff3b60f5666]), partition=
I20260812 06:19:44.403863  1960 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 17f55f266ec74a6ebd5d4ea092b7235c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:44.405987  2014 tablet_bootstrap.cc:492] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Bootstrap starting.
I20260812 06:19:44.406929  2014 tablet_bootstrap.cc:654] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.408027  2014 tablet_bootstrap.cc:492] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: No bootstrap required, opened a new log
I20260812 06:19:44.408134  2014 ts_tablet_manager.cc:1403] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:44.408632  2014 raft_consensus.cc:359] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ed909aad3a24e9b978d7ff7dcaccb87" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 39477 } }
I20260812 06:19:44.408740  2014 raft_consensus.cc:385] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.408787  2014 raft_consensus.cc:740] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1ed909aad3a24e9b978d7ff7dcaccb87, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.408946  2014 consensus_queue.cc:260] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [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: "1ed909aad3a24e9b978d7ff7dcaccb87" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 39477 } }
I20260812 06:19:44.409062  2014 raft_consensus.cc:399] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.409173  2014 raft_consensus.cc:493] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.409237  2014 raft_consensus.cc:3060] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.409992  2014 raft_consensus.cc:515] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ed909aad3a24e9b978d7ff7dcaccb87" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 39477 } }
I20260812 06:19:44.410162  2014 leader_election.cc:304] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [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: 1ed909aad3a24e9b978d7ff7dcaccb87; no voters: 
I20260812 06:19:44.410391  2014 leader_election.cc:290] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.410528  2016 raft_consensus.cc:2804] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.410781  2000 heartbeater.cc:499] Master 127.1.147.126:38589 was elected leader, sending a full tablet report...
I20260812 06:19:44.410763  2014 ts_tablet_manager.cc:1434] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:44.410769  2016 raft_consensus.cc:697] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 1 LEADER]: Becoming Leader. State: Replica: 1ed909aad3a24e9b978d7ff7dcaccb87, State: Running, Role: LEADER
I20260812 06:19:44.411060  2016 consensus_queue.cc:237] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [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: "1ed909aad3a24e9b978d7ff7dcaccb87" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 39477 } }
I20260812 06:19:44.412606  1851 catalog_manager.cc:5719] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1ed909aad3a24e9b978d7ff7dcaccb87 (127.1.147.65). New cstate: current_term: 1 leader_uuid: "1ed909aad3a24e9b978d7ff7dcaccb87" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1ed909aad3a24e9b978d7ff7dcaccb87" member_type: VOTER last_known_addr { host: "127.1.147.65" port: 39477 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:44.473469  1613 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.004s
I20260812 06:19:44.627018  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=19.054940
I20260812 06:19:44.786273  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.159s	user 0.112s	sys 0.040s Metrics: {"bytes_written":12307493,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":925,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40122,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:44.786962  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c): free 20743880 bytes of WAL
I20260812 06:19:44.787201  1935 log_reader.cc:385] T 17f55f266ec74a6ebd5d4ea092b7235c: removed 2 log segments from log reader
I20260812 06:19:44.787243  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000001 (ops 1-6)
I20260812 06:19:44.787292  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000002 (ops 7-11)
I20260812 06:19:44.791630  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:44.791955  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c): 16411393 bytes on disk
I20260812 06:19:44.792387  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.792775  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:44.812686  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.020s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6178,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.813156  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:44.945647  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.132s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":791,"lbm_read_time_us":9216,"lbm_reads_lt_1ms":460,"lbm_write_time_us":22568,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":311,"threads_started":5,"update_count":2000}
I20260812 06:19:44.946298  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:44.995038  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.049s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19149,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.995539  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:45.007812  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.008515  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:45.189601  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.181s	user 0.126s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":794,"lbm_read_time_us":11431,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34045,"lbm_writes_lt_1ms":543,"mutex_wait_us":414,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":81920,"update_count":2500}
I20260812 06:19:45.190313  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:45.235496  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.045s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19897,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.236127  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:45.409070  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.173s	user 0.108s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":924,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":467,"lbm_write_time_us":29573,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:19:45.409565  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:45.471601  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.062s	user 0.030s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25996,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.472262  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:45.485401  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.486110  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:45.683636  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.197s	user 0.139s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":481,"lbm_read_time_us":12938,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31547,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:45.684350  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:45.735306  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.051s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22431,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.735868  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:45.752535  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.753064  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:45.929837  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.177s	user 0.101s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":11483,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35365,"lbm_writes_lt_1ms":543,"mutex_wait_us":253,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:45.930653  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:45.977306  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20362,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.977927  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:45.996361  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.018s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.996922  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:46.022940  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.026s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1274,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2085,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:46.023555  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c): free 112239307 bytes of WAL
I20260812 06:19:46.023777  1935 log_reader.cc:385] T 17f55f266ec74a6ebd5d4ea092b7235c: removed 11 log segments from log reader
I20260812 06:19:46.023820  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000003 (ops 12-16)
I20260812 06:19:46.023849  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000004 (ops 17-21)
I20260812 06:19:46.023898  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000005 (ops 22-26)
I20260812 06:19:46.023928  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000006 (ops 27-31)
I20260812 06:19:46.023968  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000007 (ops 32-36)
I20260812 06:19:46.024006  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000008 (ops 37-41)
I20260812 06:19:46.024044  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000009 (ops 42-46)
I20260812 06:19:46.024081  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000010 (ops 47-50)
I20260812 06:19:46.024122  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000011 (ops 51-55)
I20260812 06:19:46.024286  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000012 (ops 56-60)
I20260812 06:19:46.024361  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000013 (ops 61-65)
I20260812 06:19:46.050988  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:46.051379  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c): 448 bytes on disk
I20260812 06:19:46.051769  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.052242  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=3.181125
I20260812 06:19:46.074739  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.022s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4799,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:46.075153  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:46.084786  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3730,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.085263  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:46.337095  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.252s	user 0.143s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1507,"lbm_read_time_us":17268,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40625,"lbm_writes_lt_1ms":743,"mutex_wait_us":702,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:19:46.338413  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=18.063937
I20260812 06:19:46.412568  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.074s	user 0.038s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":33319,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.413092  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:46.427656  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.428457  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:46.656713  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.228s	user 0.162s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1031,"lbm_read_time_us":15136,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36818,"lbm_writes_lt_1ms":643,"mutex_wait_us":329,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:19:46.657357  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=18.063937
I20260812 06:19:46.728595  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.071s	user 0.035s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27725,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.729099  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:46.739670  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.740464  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:46.943192  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.202s	user 0.113s	sys 0.089s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":15159,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34559,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":3000}
I20260812 06:19:46.944034  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:47.004181  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.060s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27633,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.004621  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:47.015436  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.015882  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:47.209857  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.194s	user 0.133s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":524,"lbm_read_time_us":13062,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33262,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52480,"update_count":2500}
I20260812 06:19:47.210558  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:47.269008  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.058s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23286,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.269573  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:47.281157  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.011s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.282080  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:47.451148  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.169s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":12966,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29379,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:47.451895  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:47.515002  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.063s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.515518  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:47.525734  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.526201  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:47.555110  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1484,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1435,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:47.555960  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c): 462 bytes on disk
I20260812 06:19:47.556336  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.556902  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:47.735255  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.178s	user 0.127s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":44,"lbm_read_time_us":12220,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28319,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:19:47.736001  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c): free 120553382 bytes of WAL
I20260812 06:19:47.736281  1935 log_reader.cc:385] T 17f55f266ec74a6ebd5d4ea092b7235c: removed 12 log segments from log reader
I20260812 06:19:47.736362  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000014 (ops 66-70)
I20260812 06:19:47.736444  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000015 (ops 71-74)
I20260812 06:19:47.736506  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000016 (ops 75-79)
I20260812 06:19:47.736567  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000017 (ops 80-84)
I20260812 06:19:47.736631  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000018 (ops 85-89)
I20260812 06:19:47.736703  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000019 (ops 90-94)
I20260812 06:19:47.736766  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000020 (ops 95-98)
I20260812 06:19:47.736826  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000021 (ops 99-103)
I20260812 06:19:47.736884  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000022 (ops 104-108)
I20260812 06:19:47.736953  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000023 (ops 109-113)
I20260812 06:19:47.737017  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000024 (ops 114-118)
I20260812 06:19:47.737090  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000025 (ops 119-123)
I20260812 06:19:47.765414  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:47.765866  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=18.063937
I20260812 06:19:47.836087  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.070s	user 0.040s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27770,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:47.836723  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:47.848356  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.848839  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:48.043630  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.195s	user 0.131s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":14967,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33467,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":3000}
I20260812 06:19:48.048039  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:48.098869  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.051s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22275,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.099381  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:48.117106  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.117663  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:48.289728  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.172s	user 0.140s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":12491,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28647,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:48.290311  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:48.354128  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.064s	user 0.028s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.354893  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:48.368086  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.013s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.368800  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:48.554493  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.186s	user 0.121s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":14844,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31755,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:48.555231  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=10.126437
I20260812 06:19:48.594105  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16853,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.594719  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:48.611146  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6708,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.611889  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:48.746662  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.135s	user 0.095s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":573,"lbm_read_time_us":9928,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24750,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:19:48.747648  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=10.126437
I20260812 06:19:48.794416  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.047s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18850,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.794901  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:48.805918  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.806677  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:48.940168  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.133s	user 0.112s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":10827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25896,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":40064,"update_count":2000}
I20260812 06:19:48.940936  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=10.126437
I20260812 06:19:48.995440  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.054s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18547,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.995899  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:49.006196  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.006739  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:49.036584  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushMRSOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1481,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1740,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:49.037304  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c): free 120553562 bytes of WAL
I20260812 06:19:49.037520  1935 log_reader.cc:385] T 17f55f266ec74a6ebd5d4ea092b7235c: removed 12 log segments from log reader
I20260812 06:19:49.037564  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000026 (ops 124-128)
I20260812 06:19:49.037591  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000027 (ops 129-133)
I20260812 06:19:49.037654  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000028 (ops 134-138)
I20260812 06:19:49.037699  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000029 (ops 139-143)
I20260812 06:19:49.037739  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000030 (ops 144-148)
I20260812 06:19:49.037779  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000031 (ops 149-153)
I20260812 06:19:49.037814  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000032 (ops 154-158)
I20260812 06:19:49.037855  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000033 (ops 159-162)
I20260812 06:19:49.037897  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000034 (ops 163-167)
I20260812 06:19:49.037937  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000035 (ops 168-172)
I20260812 06:19:49.037981  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000036 (ops 173-176)
I20260812 06:19:49.038024  1935 log.cc:1079] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: Deleting log segment in path: /tmp/dist-test-taskwPp6Mi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515578959111-1613-0/minicluster-data/ts-0-root/wals/17f55f266ec74a6ebd5d4ea092b7235c/wal-000000037 (ops 177-181)
I20260812 06:19:49.065198  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: LogGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:49.065608  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c): 447 bytes on disk
I20260812 06:19:49.066138  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: UndoDeltaBlockGCOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.066843  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=3.181125
I20260812 06:19:49.079221  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:49.079664  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:49.090196  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.090823  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:49.265282  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.174s	user 0.125s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":48,"lbm_read_time_us":13715,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34699,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"thread_start_us":125,"threads_started":1,"update_count":3000}
I20260812 06:19:49.266062  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:49.324003  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.058s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25483,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.324561  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=2.188937
I20260812 06:19:49.339550  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.340175  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:49.509454  1613 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.036s	user 1.820s	sys 0.215s
I20260812 06:19:49.521194  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.181s	user 0.124s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":851,"lbm_read_time_us":12787,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32192,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":75008,"update_count":2500}
I20260812 06:19:49.521775  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=14.095187
I20260812 06:19:49.580994  1613 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:19:49.582106  1613 tablet_server.cc:179] TabletServer@127.1.147.65:0 shutting down...
I20260812 06:19:49.583003  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: FlushDeltaMemStoresOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.061s	user 0.028s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":27227,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.583596  2001 maintenance_manager.cc:419] P 1ed909aad3a24e9b978d7ff7dcaccb87: Scheduling MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c): perf score=1.000000
I20260812 06:19:49.703675  1935 maintenance_manager.cc:643] P 1ed909aad3a24e9b978d7ff7dcaccb87: MajorDeltaCompactionOp(17f55f266ec74a6ebd5d4ea092b7235c) complete. Timing: real 0.120s	user 0.096s	sys 0.023s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":401,"cfile_cache_miss_bytes":16409770,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":767,"lbm_read_time_us":7462,"lbm_reads_lt_1ms":413,"lbm_write_time_us":20351,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:49.704694  1613 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:49.704995  1613 tablet_replica.cc:333] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87: stopping tablet replica
I20260812 06:19:49.705165  1613 raft_consensus.cc:2243] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.705377  1613 raft_consensus.cc:2272] T 17f55f266ec74a6ebd5d4ea092b7235c P 1ed909aad3a24e9b978d7ff7dcaccb87 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.711611  1613 tablet_server.cc:196] TabletServer@127.1.147.65:0 shutdown complete.
I20260812 06:19:49.743999  1613 master.cc:562] Master@127.1.147.126:38589 shutting down...
I20260812 06:19:49.747184  1613 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.747339  1613 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.747386  1613 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6f0923fc02364ad498d2715b63749d18: stopping tablet replica
I20260812 06:19:49.759639  1613 master.cc:584] Master@127.1.147.126:38589 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5592 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10883 ms total)

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