[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:17.923720  7236 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.17.62:37155
I20260812 06:18:17.924938  7236 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:17.925596  7236 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:17.932255  7241 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:17.932235  7243 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.932503  7236 server_base.cc:1061] running on GCE node
W20260812 06:18:17.932559  7245 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:17.933075  7236 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:17.933200  7236 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:17.933264  7236 hybrid_clock.cc:648] HybridClock initialized: now 1786515497933261 us; error 0 us; skew 500 ppm
I20260812 06:18:17.935178  7236 webserver.cc:533] Webserver started at http://127.7.17.62:38485/ using document root <none> and password file <none>
I20260812 06:18:17.935778  7236 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:17.935869  7236 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:17.936177  7236 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:17.937927  7236 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/master-0-root/instance:
uuid: "a5ba6d15dbf5474c8b55e85f039f2638"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-8w9v"
I20260812 06:18:17.942539  7236 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:18:17.945317  7251 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:17.946552  7236 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:17.946723  7236 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/master-0-root
uuid: "a5ba6d15dbf5474c8b55e85f039f2638"
format_stamp: "Formatted at 2026-08-12 06:18:17 on dist-test-slave-8w9v"
I20260812 06:18:17.946851  7236 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:17.958693  7236 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:17.959335  7236 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:17.959522  7236 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:17.967608  7236 rpc_server.cc:307] RPC server started. Bound to: 127.7.17.62:37155
I20260812 06:18:17.967621  7314 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.17.62:37155 every 8 connection(s)
I20260812 06:18:17.969941  7315 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:17.975592  7315 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: Bootstrap starting.
I20260812 06:18:17.978185  7315 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:17.979203  7315 log.cc:826] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:17.981145  7315 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: No bootstrap required, opened a new log
I20260812 06:18:17.984150  7315 raft_consensus.cc:359] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER }
I20260812 06:18:17.984342  7315 raft_consensus.cc:385] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:17.984422  7315 raft_consensus.cc:740] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a5ba6d15dbf5474c8b55e85f039f2638, State: Initialized, Role: FOLLOWER
I20260812 06:18:17.985106  7315 consensus_queue.cc:260] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [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: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER }
I20260812 06:18:17.985255  7315 raft_consensus.cc:399] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:17.985352  7315 raft_consensus.cc:493] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:17.985531  7315 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:17.986423  7315 raft_consensus.cc:515] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER }
I20260812 06:18:17.986907  7315 leader_election.cc:304] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [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: a5ba6d15dbf5474c8b55e85f039f2638; no voters: 
I20260812 06:18:17.987264  7315 leader_election.cc:290] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:17.987439  7318 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:17.987747  7318 raft_consensus.cc:697] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 1 LEADER]: Becoming Leader. State: Replica: a5ba6d15dbf5474c8b55e85f039f2638, State: Running, Role: LEADER
I20260812 06:18:17.988247  7318 consensus_queue.cc:237] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [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: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER }
I20260812 06:18:17.988463  7315 sys_catalog.cc:565] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:17.990317  7319 sys_catalog.cc:455] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER } }
I20260812 06:18:17.990360  7320 sys_catalog.cc:455] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a5ba6d15dbf5474c8b55e85f039f2638. Latest consensus state: current_term: 1 leader_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a5ba6d15dbf5474c8b55e85f039f2638" member_type: VOTER } }
I20260812 06:18:17.990455  7319 sys_catalog.cc:458] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.990455  7320 sys_catalog.cc:458] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:17.990837  7333 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:17.991055  7236 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:17.993419  7333 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:17.998606  7333 catalog_manager.cc:1383] Generated new cluster ID: 3fb62282691f4ed98f44916c4f1256be
I20260812 06:18:17.998688  7333 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:18.008103  7333 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:18.009109  7333 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:18.018951  7333 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: Generated new TSK 0
I20260812 06:18:18.019681  7333 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:18.023722  7236 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:18.026908  7342 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:18.026895  7344 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:18.026858  7341 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:18.027065  7236 server_base.cc:1061] running on GCE node
I20260812 06:18:18.027374  7236 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:18.027419  7236 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:18.027436  7236 hybrid_clock.cc:648] HybridClock initialized: now 1786515498027435 us; error 0 us; skew 500 ppm
I20260812 06:18:18.028468  7236 webserver.cc:533] Webserver started at http://127.7.17.1:44483/ using document root <none> and password file <none>
I20260812 06:18:18.028664  7236 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:18.028719  7236 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:18.028826  7236 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:18.029253  7236 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/instance:
uuid: "cd4a65e34df64ce5b2cecc4e43848e57"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-8w9v"
I20260812 06:18:18.030895  7236 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:18.032001  7350 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.032325  7236 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:18.032420  7236 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root
uuid: "cd4a65e34df64ce5b2cecc4e43848e57"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-8w9v"
I20260812 06:18:18.032512  7236 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:18.047942  7236 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:18.048882  7236 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:18.049372  7236 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:18.050273  7236 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:18.050354  7236 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.050433  7236 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:18.050475  7236 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.057418  7236 rpc_server.cc:307] RPC server started. Bound to: 127.7.17.1:42999
I20260812 06:18:18.057452  7422 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.17.1:42999 every 8 connection(s)
I20260812 06:18:18.072225  7423 heartbeater.cc:344] Connected to a master server at 127.7.17.62:37155
I20260812 06:18:18.072567  7423 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:18.073093  7423 heartbeater.cc:507] Master 127.7.17.62:37155 requested a full tablet report, sending...
I20260812 06:18:18.074765  7271 ts_manager.cc:194] Registered new tserver with Master: cd4a65e34df64ce5b2cecc4e43848e57 (127.7.17.1:42999)
I20260812 06:18:18.074873  7236 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01680011s
I20260812 06:18:18.076208  7271 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42022
I20260812 06:18:18.085631  7271 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42030:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:18.101392  7384 tablet_service.cc:1511] Processing CreateTablet for tablet 047265318806443792e22393ad6e4a10 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b069d9528b864a3da6883eeae0072eb2]), partition=
I20260812 06:18:18.101935  7384 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 047265318806443792e22393ad6e4a10. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:18.104974  7437 tablet_bootstrap.cc:492] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Bootstrap starting.
I20260812 06:18:18.106185  7437 tablet_bootstrap.cc:654] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:18.107482  7437 tablet_bootstrap.cc:492] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: No bootstrap required, opened a new log
I20260812 06:18:18.107612  7437 ts_tablet_manager.cc:1403] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:18.108086  7437 raft_consensus.cc:359] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd4a65e34df64ce5b2cecc4e43848e57" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 42999 } }
I20260812 06:18:18.108280  7437 raft_consensus.cc:385] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:18.108351  7437 raft_consensus.cc:740] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cd4a65e34df64ce5b2cecc4e43848e57, State: Initialized, Role: FOLLOWER
I20260812 06:18:18.108554  7437 consensus_queue.cc:260] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [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: "cd4a65e34df64ce5b2cecc4e43848e57" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 42999 } }
I20260812 06:18:18.108680  7437 raft_consensus.cc:399] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:18.108739  7437 raft_consensus.cc:493] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:18.108841  7437 raft_consensus.cc:3060] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:18.109836  7437 raft_consensus.cc:515] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd4a65e34df64ce5b2cecc4e43848e57" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 42999 } }
I20260812 06:18:18.110000  7437 leader_election.cc:304] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [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: cd4a65e34df64ce5b2cecc4e43848e57; no voters: 
I20260812 06:18:18.110368  7437 leader_election.cc:290] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:18.110481  7439 raft_consensus.cc:2804] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:18.110679  7439 raft_consensus.cc:697] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 1 LEADER]: Becoming Leader. State: Replica: cd4a65e34df64ce5b2cecc4e43848e57, State: Running, Role: LEADER
I20260812 06:18:18.110786  7437 ts_tablet_manager.cc:1434] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:18.110893  7439 consensus_queue.cc:237] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [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: "cd4a65e34df64ce5b2cecc4e43848e57" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 42999 } }
I20260812 06:18:18.111145  7423 heartbeater.cc:499] Master 127.7.17.62:37155 was elected leader, sending a full tablet report...
I20260812 06:18:18.113946  7271 catalog_manager.cc:5719] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 reported cstate change: term changed from 0 to 1, leader changed from <none> to cd4a65e34df64ce5b2cecc4e43848e57 (127.7.17.1). New cstate: current_term: 1 leader_uuid: "cd4a65e34df64ce5b2cecc4e43848e57" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cd4a65e34df64ce5b2cecc4e43848e57" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 42999 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:18.183162  7236 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.016s	sys 0.012s
I20260812 06:18:18.308696  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushMRSOp(047265318806443792e22393ad6e4a10): perf score=15.086190
I20260812 06:18:18.487393  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushMRSOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.178s	user 0.129s	sys 0.044s Metrics: {"bytes_written":14235626,"cfile_init":1,"compiler_manager_pool.queue_time_us":213,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":982,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42986,"lbm_writes_lt_1ms":704,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":46720,"thread_start_us":135,"threads_started":1,"update_count":1735}
I20260812 06:18:18.488721  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10): 12308958 bytes on disk
I20260812 06:18:18.489358  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.489820  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:18.501731  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3651388,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:18.502249  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling LogGCOp(047265318806443792e22393ad6e4a10): free 11976772 bytes of WAL
I20260812 06:18:18.502549  7355 log_reader.cc:385] T 047265318806443792e22393ad6e4a10: removed 1 log segments from log reader
I20260812 06:18:18.502636  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000001 (ops 1-6)
I20260812 06:18:18.505800  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: LogGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:18.506276  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=1.196750
I20260812 06:18:18.516776  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":3619,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:18:18.517333  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:18.696187  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.179s	user 0.115s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733803,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":10434,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31909,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":329,"threads_started":5,"update_count":2500}
I20260812 06:18:18.696832  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:18.742175  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.045s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14576,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.742774  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:18.757915  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.758545  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:18.899191  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.140s	user 0.096s	sys 0.040s 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":1084,"lbm_read_time_us":9827,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27075,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2000}
I20260812 06:18:18.899951  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=11.118625
I20260812 06:18:18.936868  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.037s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16182,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.937566  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:18.949560  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.950169  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.083810  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.133s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":552,"lbm_read_time_us":7334,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28133,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:19.084719  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=11.118625
I20260812 06:18:19.126175  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.041s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17999,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.126749  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:19.138370  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4224,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.138861  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.266881  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.128s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":8936,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23508,"lbm_writes_lt_1ms":443,"mutex_wait_us":257,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2000}
I20260812 06:18:19.268987  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:19.320276  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.051s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20162,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.320891  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:19.332849  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.333412  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.490089  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.156s	user 0.100s	sys 0.056s 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":229,"lbm_read_time_us":12481,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24272,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:18:19.490758  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:19.530278  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.039s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15741,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.530803  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:19.542265  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.009s	sys 0.000s 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:18:19.542922  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.667321  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.124s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1125,"lbm_read_time_us":7863,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25597,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:19.667914  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:19.716889  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.049s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.717438  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:19.729787  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.730459  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushMRSOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.764525  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushMRSOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1509,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:19.765501  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling LogGCOp(047265318806443792e22393ad6e4a10): free 120553386 bytes of WAL
I20260812 06:18:19.765781  7355 log_reader.cc:385] T 047265318806443792e22393ad6e4a10: removed 12 log segments from log reader
I20260812 06:18:19.765853  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000002 (ops 7-11)
I20260812 06:18:19.765908  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000003 (ops 12-16)
I20260812 06:18:19.765954  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000004 (ops 17-21)
I20260812 06:18:19.765992  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000005 (ops 22-26)
I20260812 06:18:19.766031  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000006 (ops 27-31)
I20260812 06:18:19.766068  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000007 (ops 32-36)
I20260812 06:18:19.766105  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000008 (ops 37-41)
I20260812 06:18:19.766142  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000009 (ops 42-46)
I20260812 06:18:19.766179  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000010 (ops 47-50)
I20260812 06:18:19.766215  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000011 (ops 51-55)
I20260812 06:18:19.766252  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000012 (ops 56-60)
I20260812 06:18:19.766289  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000013 (ops 61-64)
I20260812 06:18:19.790452  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: LogGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.025s	user 0.009s	sys 0.015s Metrics: {}
I20260812 06:18:19.790977  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10): 462 bytes on disk
I20260812 06:18:19.791491  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.792059  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=3.181125
I20260812 06:18:19.804874  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:19.805308  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:19.816022  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3677,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.816670  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:19.998858  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.182s	user 0.130s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836365,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":798,"lbm_read_time_us":12308,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37081,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:19.999469  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=14.095187
I20260812 06:18:20.053856  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.054s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23419,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.054523  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:20.066341  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.067183  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:20.235589  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.168s	user 0.109s	sys 0.046s 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":441,"lbm_read_time_us":10556,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30279,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:20.236304  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=14.095187
I20260812 06:18:20.292028  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.055s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24377,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.292621  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:20.440802  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.148s	user 0.106s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631190,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1689,"lbm_read_time_us":11118,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24603,"lbm_writes_lt_1ms":443,"mutex_wait_us":620,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:20.441408  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:20.481011  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.039s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.481649  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:20.494514  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.495031  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:20.628027  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.133s	user 0.115s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1290,"lbm_read_time_us":9382,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25656,"lbm_writes_lt_1ms":443,"mutex_wait_us":380,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:18:20.628808  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:20.674861  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.046s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17032,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.675361  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:20.686525  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.687130  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:20.814041  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.127s	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":1171,"lbm_read_time_us":9067,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24731,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:18:20.814765  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:20.865474  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.051s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.866154  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:20.878250  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.878934  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:21.010016  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.131s	user 0.087s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":782,"lbm_read_time_us":10401,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27355,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:21.010619  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:21.060101  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.049s	user 0.024s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17539,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.060765  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.071947  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.072603  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:21.232249  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.159s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":831,"lbm_read_time_us":12500,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27791,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:21.233047  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:21.285388  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.052s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19456,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.285966  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.298491  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.299019  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushMRSOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:21.326449  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushMRSOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1361,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1572,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:21.327476  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling LogGCOp(047265318806443792e22393ad6e4a10): free 133024366 bytes of WAL
I20260812 06:18:21.327785  7355 log_reader.cc:385] T 047265318806443792e22393ad6e4a10: removed 13 log segments from log reader
I20260812 06:18:21.327862  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000014 (ops 65-69)
I20260812 06:18:21.327904  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000015 (ops 70-74)
I20260812 06:18:21.327936  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000016 (ops 75-79)
I20260812 06:18:21.327960  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000017 (ops 80-84)
I20260812 06:18:21.327992  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000018 (ops 85-89)
I20260812 06:18:21.328025  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000019 (ops 90-94)
I20260812 06:18:21.328048  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000020 (ops 95-99)
I20260812 06:18:21.328078  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000021 (ops 100-104)
I20260812 06:18:21.328106  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000022 (ops 105-108)
I20260812 06:18:21.328167  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000023 (ops 109-113)
I20260812 06:18:21.328204  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000024 (ops 114-118)
I20260812 06:18:21.328236  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000025 (ops 119-123)
I20260812 06:18:21.328262  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000026 (ops 124-128)
I20260812 06:18:21.362046  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: LogGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.034s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:18:21.362594  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10): 482 bytes on disk
I20260812 06:18:21.363318  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.364192  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.395210  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.031s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.395850  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.408807  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.409421  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:21.610391  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.201s	user 0.152s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":154,"lbm_read_time_us":14743,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33579,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14848,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:21.611202  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=14.095187
I20260812 06:18:21.673346  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.062s	user 0.002s	sys 0.048s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18676,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.673926  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.685492  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.686034  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:21.870517  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.184s	user 0.139s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":601,"lbm_read_time_us":12845,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33470,"lbm_writes_lt_1ms":543,"mutex_wait_us":266,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:21.871351  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=11.118625
I20260812 06:18:21.919171  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.048s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17764,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:21.919715  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.937487  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.018s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.937965  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:21.956823  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3621,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.957376  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:22.148524  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.191s	user 0.135s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":399,"lbm_read_time_us":15117,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33507,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":168064,"update_count":2500}
I20260812 06:18:22.149019  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=11.118625
I20260812 06:18:22.179761  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.031s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13772,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:22.180521  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.198395  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6804,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.198971  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:22.336265  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.137s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":8076,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29362,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.337016  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:22.370352  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.033s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.371603  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.389518  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.390028  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:22.524626  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.134s	user 0.098s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1227,"lbm_read_time_us":9763,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27995,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:22.525400  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:22.572664  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.047s	user 0.029s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22126,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.573292  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.590159  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.590728  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:22.715098  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.124s	user 0.093s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1244,"lbm_read_time_us":8535,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25061,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:22.715832  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:22.772414  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.056s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17882,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.773023  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.783962  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.784647  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushMRSOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:22.828979  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushMRSOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.044s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1569,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:22.829873  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling LogGCOp(047265318806443792e22393ad6e4a10): free 108988743 bytes of WAL
I20260812 06:18:22.830138  7355 log_reader.cc:385] T 047265318806443792e22393ad6e4a10: removed 11 log segments from log reader
I20260812 06:18:22.830210  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000027 (ops 129-133)
I20260812 06:18:22.830266  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000028 (ops 134-138)
I20260812 06:18:22.830329  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000029 (ops 139-143)
I20260812 06:18:22.830374  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000030 (ops 144-148)
I20260812 06:18:22.830415  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000031 (ops 149-152)
I20260812 06:18:22.830454  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000032 (ops 153-157)
I20260812 06:18:22.830493  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000033 (ops 158-162)
I20260812 06:18:22.830533  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000034 (ops 163-167)
I20260812 06:18:22.830574  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000035 (ops 168-172)
I20260812 06:18:22.830613  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000036 (ops 173-177)
I20260812 06:18:22.830653  7355 log.cc:1079] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/047265318806443792e22393ad6e4a10/wal-000000037 (ops 178-182)
I20260812 06:18:22.855016  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: LogGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:22.855545  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.871136  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.871686  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=2.188937
I20260812 06:18:22.882454  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.883126  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:23.073597  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.190s	user 0.119s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1042,"lbm_read_time_us":13390,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32379,"lbm_writes_lt_1ms":643,"mutex_wait_us":255,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:23.074427  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=14.095187
I20260812 06:18:23.126027  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.051s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.126598  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10): 447 bytes on disk
I20260812 06:18:23.126984  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: UndoDeltaBlockGCOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.127497  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:23.244093  7236 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.061s	user 1.833s	sys 0.168s
I20260812 06:18:23.262380  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.135s	user 0.090s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631196,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":9679,"lbm_reads_lt_1ms":459,"lbm_write_time_us":23474,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.262956  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10): perf score=10.126437
I20260812 06:18:23.295486  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: FlushDeltaMemStoresOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.032s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14357,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:23.296047  7236 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.051s	user 0.000s	sys 0.001s
I20260812 06:18:23.296057  7424 maintenance_manager.cc:419] P cd4a65e34df64ce5b2cecc4e43848e57: Scheduling MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10): perf score=1.000000
I20260812 06:18:23.296730  7236 tablet_server.cc:179] TabletServer@127.7.17.1:0 shutting down...
I20260812 06:18:23.396059  7355 maintenance_manager.cc:643] P cd4a65e34df64ce5b2cecc4e43848e57: MajorDeltaCompactionOp(047265318806443792e22393ad6e4a10) complete. Timing: real 0.100s	user 0.070s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":290,"lbm_read_time_us":8211,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17066,"lbm_writes_lt_1ms":343,"mutex_wait_us":30,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":151040,"update_count":1500}
I20260812 06:18:23.396984  7236 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:23.397441  7236 tablet_replica.cc:333] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57: stopping tablet replica
I20260812 06:18:23.397693  7236 raft_consensus.cc:2243] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.397943  7236 raft_consensus.cc:2272] T 047265318806443792e22393ad6e4a10 P cd4a65e34df64ce5b2cecc4e43848e57 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.413851  7236 tablet_server.cc:196] TabletServer@127.7.17.1:0 shutdown complete.
I20260812 06:18:23.431777  7236 master.cc:562] Master@127.7.17.62:37155 shutting down...
I20260812 06:18:23.436228  7236 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.436455  7236 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.436556  7236 tablet_replica.cc:333] T 00000000000000000000000000000000 P a5ba6d15dbf5474c8b55e85f039f2638: stopping tablet replica
I20260812 06:18:23.449008  7236 master.cc:584] Master@127.7.17.62:37155 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5625 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:23.549224  7236 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.17.62:38131
I20260812 06:18:23.549636  7236 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:23.552014  7460 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:23.552053  7459 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:23.552189  7462 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:23.552265  7236 server_base.cc:1061] running on GCE node
I20260812 06:18:23.552461  7236 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:23.552518  7236 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:23.552544  7236 hybrid_clock.cc:648] HybridClock initialized: now 1786515503552544 us; error 0 us; skew 500 ppm
I20260812 06:18:23.553589  7236 webserver.cc:533] Webserver started at http://127.7.17.62:36165/ using document root <none> and password file <none>
I20260812 06:18:23.553782  7236 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:23.553846  7236 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:23.553941  7236 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:23.554477  7236 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/master-0-root/instance:
uuid: "13b1d60b2227433d90b091e1c529e6ff"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-8w9v"
I20260812 06:18:23.556780  7236 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:23.558080  7467 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.558396  7236 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:23.558488  7236 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/master-0-root
uuid: "13b1d60b2227433d90b091e1c529e6ff"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-8w9v"
I20260812 06:18:23.558578  7236 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:23.570025  7236 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:23.570415  7236 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:23.575181  7236 rpc_server.cc:307] RPC server started. Bound to: 127.7.17.62:38131
I20260812 06:18:23.579778  7533 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.17.62:38131 every 8 connection(s)
I20260812 06:18:23.580078  7534 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:23.585423  7534 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff: Bootstrap starting.
I20260812 06:18:23.586321  7534 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:23.587486  7534 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff: No bootstrap required, opened a new log
I20260812 06:18:23.587915  7534 raft_consensus.cc:359] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER }
I20260812 06:18:23.588032  7534 raft_consensus.cc:385] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:23.588096  7534 raft_consensus.cc:740] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 13b1d60b2227433d90b091e1c529e6ff, State: Initialized, Role: FOLLOWER
I20260812 06:18:23.588286  7534 consensus_queue.cc:260] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [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: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER }
I20260812 06:18:23.588397  7534 raft_consensus.cc:399] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:23.588442  7534 raft_consensus.cc:493] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:23.588495  7534 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:23.589248  7534 raft_consensus.cc:515] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER }
I20260812 06:18:23.589423  7534 leader_election.cc:304] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [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: 13b1d60b2227433d90b091e1c529e6ff; no voters: 
I20260812 06:18:23.589651  7534 leader_election.cc:290] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:23.589816  7537 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:23.590065  7537 raft_consensus.cc:697] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 1 LEADER]: Becoming Leader. State: Replica: 13b1d60b2227433d90b091e1c529e6ff, State: Running, Role: LEADER
I20260812 06:18:23.590152  7534 sys_catalog.cc:565] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:23.590241  7537 consensus_queue.cc:237] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [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: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER }
I20260812 06:18:23.590772  7539 sys_catalog.cc:455] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [sys.catalog]: SysCatalogTable state changed. Reason: New leader 13b1d60b2227433d90b091e1c529e6ff. Latest consensus state: current_term: 1 leader_uuid: "13b1d60b2227433d90b091e1c529e6ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER } }
I20260812 06:18:23.590749  7538 sys_catalog.cc:455] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "13b1d60b2227433d90b091e1c529e6ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "13b1d60b2227433d90b091e1c529e6ff" member_type: VOTER } }
I20260812 06:18:23.590960  7538 sys_catalog.cc:458] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:23.591212  7539 sys_catalog.cc:458] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:23.591419  7546 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:23.592083  7546 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:23.592324  7236 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:23.593948  7546 catalog_manager.cc:1383] Generated new cluster ID: 4baabd8168d74beabc972347a1d7bdc0
I20260812 06:18:23.594009  7546 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:23.604664  7546 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:23.605245  7546 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:23.610519  7546 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff: Generated new TSK 0
I20260812 06:18:23.610713  7546 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:23.624861  7236 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:23.627126  7236 server_base.cc:1061] running on GCE node
W20260812 06:18:23.627168  7560 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:23.627089  7558 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:23.627089  7557 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:23.627478  7236 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:23.627522  7236 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:23.627538  7236 hybrid_clock.cc:648] HybridClock initialized: now 1786515503627538 us; error 0 us; skew 500 ppm
I20260812 06:18:23.628535  7236 webserver.cc:533] Webserver started at http://127.7.17.1:34287/ using document root <none> and password file <none>
I20260812 06:18:23.628723  7236 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:23.628806  7236 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:23.628902  7236 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:23.629325  7236 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/instance:
uuid: "4f55a84e4884459295ac45b2ff6f2438"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-8w9v"
I20260812 06:18:23.630913  7236 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:23.631880  7565 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.632104  7236 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:23.632248  7236 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root
uuid: "4f55a84e4884459295ac45b2ff6f2438"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-8w9v"
I20260812 06:18:23.632341  7236 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:23.643489  7236 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:23.643934  7236 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:23.644340  7236 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:23.644851  7236 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:23.644914  7236 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.644966  7236 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:23.645018  7236 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.649605  7236 rpc_server.cc:307] RPC server started. Bound to: 127.7.17.1:35707
I20260812 06:18:23.651700  7638 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.17.1:35707 every 8 connection(s)
I20260812 06:18:23.656739  7639 heartbeater.cc:344] Connected to a master server at 127.7.17.62:38131
I20260812 06:18:23.656842  7639 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:23.657047  7639 heartbeater.cc:507] Master 127.7.17.62:38131 requested a full tablet report, sending...
I20260812 06:18:23.657671  7486 ts_manager.cc:194] Registered new tserver with Master: 4f55a84e4884459295ac45b2ff6f2438 (127.7.17.1:35707)
I20260812 06:18:23.658365  7486 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:32790
I20260812 06:18:23.658406  7236 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007817124s
I20260812 06:18:23.665819  7486 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:32798:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:23.675554  7596 tablet_service.cc:1511] Processing CreateTablet for tablet 6780aa5f03004ae2b7a246a0abf9ec91 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c0f12eb3272a4d6eb3b6571619bc29ff]), partition=
I20260812 06:18:23.675923  7596 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6780aa5f03004ae2b7a246a0abf9ec91. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:23.678437  7657 tablet_bootstrap.cc:492] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Bootstrap starting.
I20260812 06:18:23.679350  7657 tablet_bootstrap.cc:654] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:23.680646  7657 tablet_bootstrap.cc:492] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: No bootstrap required, opened a new log
I20260812 06:18:23.680823  7657 ts_tablet_manager.cc:1403] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:23.681305  7657 raft_consensus.cc:359] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f55a84e4884459295ac45b2ff6f2438" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 35707 } }
I20260812 06:18:23.681404  7657 raft_consensus.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:23.681428  7657 raft_consensus.cc:740] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f55a84e4884459295ac45b2ff6f2438, State: Initialized, Role: FOLLOWER
I20260812 06:18:23.681527  7657 consensus_queue.cc:260] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [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: "4f55a84e4884459295ac45b2ff6f2438" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 35707 } }
I20260812 06:18:23.681588  7657 raft_consensus.cc:399] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:23.681612  7657 raft_consensus.cc:493] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:23.681645  7657 raft_consensus.cc:3060] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:23.682343  7657 raft_consensus.cc:515] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f55a84e4884459295ac45b2ff6f2438" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 35707 } }
I20260812 06:18:23.682461  7657 leader_election.cc:304] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [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: 4f55a84e4884459295ac45b2ff6f2438; no voters: 
I20260812 06:18:23.682634  7657 leader_election.cc:290] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:23.682788  7660 raft_consensus.cc:2804] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:23.682948  7657 ts_tablet_manager.cc:1434] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:23.682968  7639 heartbeater.cc:499] Master 127.7.17.62:38131 was elected leader, sending a full tablet report...
I20260812 06:18:23.683046  7660 raft_consensus.cc:697] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 1 LEADER]: Becoming Leader. State: Replica: 4f55a84e4884459295ac45b2ff6f2438, State: Running, Role: LEADER
I20260812 06:18:23.683205  7660 consensus_queue.cc:237] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [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: "4f55a84e4884459295ac45b2ff6f2438" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 35707 } }
I20260812 06:18:23.684613  7486 catalog_manager.cc:5719] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4f55a84e4884459295ac45b2ff6f2438 (127.7.17.1). New cstate: current_term: 1 leader_uuid: "4f55a84e4884459295ac45b2ff6f2438" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f55a84e4884459295ac45b2ff6f2438" member_type: VOTER last_known_addr { host: "127.7.17.1" port: 35707 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:23.744527  7236 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.015s	sys 0.008s
I20260812 06:18:23.902383  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=19.054940
I20260812 06:18:24.076522  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.174s	user 0.121s	sys 0.052s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":987,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44396,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:24.077229  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91): free 20743880 bytes of WAL
I20260812 06:18:24.077468  7570 log_reader.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91: removed 2 log segments from log reader
I20260812 06:18:24.077513  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000001 (ops 1-6)
I20260812 06:18:24.077545  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000002 (ops 7-11)
I20260812 06:18:24.082129  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:24.082634  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91): 16411396 bytes on disk
I20260812 06:18:24.083163  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.083614  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:24.100373  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.100931  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:24.258463  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.157s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":575,"lbm_read_time_us":11380,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25142,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":45824,"thread_start_us":316,"threads_started":5,"update_count":2000}
I20260812 06:18:24.259147  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:24.311719  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.052s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20347,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.312371  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:24.323858  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.324512  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:24.504271  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.180s	user 0.119s	sys 0.053s 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":653,"lbm_read_time_us":11777,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28904,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:18:24.504997  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:24.570199  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.065s	user 0.031s	sys 0.032s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24230,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.570803  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:24.588485  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.589120  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:24.768615  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.179s	user 0.128s	sys 0.048s 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":220,"lbm_read_time_us":13198,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27543,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2500}
I20260812 06:18:24.769241  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:24.834342  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.065s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22116,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.834897  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:24.845561  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.846069  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:25.033821  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.188s	user 0.107s	sys 0.074s 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":194,"lbm_read_time_us":12702,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29387,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:25.034478  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:25.084713  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.050s	user 0.015s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18435,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:25.085237  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:25.098369  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.098870  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:25.283779  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.185s	user 0.119s	sys 0.062s 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":235,"lbm_read_time_us":11891,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29315,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:25.284446  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:25.342356  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.058s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.342911  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:25.354324  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.354842  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:25.387213  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.032s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2041,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:25.387867  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91): free 112692367 bytes of WAL
I20260812 06:18:25.388090  7570 log_reader.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91: removed 11 log segments from log reader
I20260812 06:18:25.388172  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000003 (ops 12-16)
I20260812 06:18:25.388230  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000004 (ops 17-21)
I20260812 06:18:25.388273  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000005 (ops 22-26)
I20260812 06:18:25.388310  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000006 (ops 27-31)
I20260812 06:18:25.388355  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000007 (ops 32-36)
I20260812 06:18:25.388391  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000008 (ops 37-41)
I20260812 06:18:25.388435  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000009 (ops 42-46)
I20260812 06:18:25.388471  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000010 (ops 47-51)
I20260812 06:18:25.388509  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000011 (ops 52-56)
I20260812 06:18:25.388545  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000012 (ops 57-61)
I20260812 06:18:25.388582  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000013 (ops 62-66)
I20260812 06:18:25.412371  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.024s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:25.412767  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:25.441107  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.028s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.441730  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91): free 11564875 bytes of WAL
I20260812 06:18:25.441992  7570 log_reader.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91: removed 1 log segments from log reader
I20260812 06:18:25.442054  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000014 (ops 67-70)
I20260812 06:18:25.444917  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:25.445286  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91): 463 bytes on disk
I20260812 06:18:25.445746  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.446187  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:25.457028  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.011s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.457471  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:25.705823  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.248s	user 0.150s	sys 0.086s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":811,"lbm_read_time_us":16778,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38169,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":113,"threads_started":1,"update_count":3500}
I20260812 06:18:25.706789  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=18.063937
I20260812 06:18:25.781594  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.075s	user 0.054s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30310,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.782074  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:25.793704  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.794507  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:26.005447  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.211s	user 0.138s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1115,"lbm_read_time_us":12663,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36611,"lbm_writes_lt_1ms":643,"mutex_wait_us":736,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":3000}
I20260812 06:18:26.006242  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:26.063576  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.057s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24213,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.064200  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.090417  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.026s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.090950  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.103484  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.104274  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:26.320106  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.216s	user 0.138s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1112,"lbm_read_time_us":15539,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36255,"lbm_writes_lt_1ms":643,"mutex_wait_us":306,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":3000}
I20260812 06:18:26.320943  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:26.381716  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.061s	user 0.044s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23780,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.382267  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.393806  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.394338  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:26.578927  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.184s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":82,"lbm_read_time_us":12433,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30860,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":73088,"update_count":2500}
I20260812 06:18:26.579720  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:26.643013  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.063s	user 0.034s	sys 0.027s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24953,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.643606  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.670450  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.670955  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.685987  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.686681  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:26.911213  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.224s	user 0.149s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877223,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":411,"lbm_read_time_us":16000,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38264,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":3000}
I20260812 06:18:26.911809  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:26.980453  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.068s	user 0.027s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.981024  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:26.997090  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.997777  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:27.032807  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1492,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2051,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:27.033615  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91): free 117302573 bytes of WAL
I20260812 06:18:27.033844  7570 log_reader.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91: removed 12 log segments from log reader
I20260812 06:18:27.033896  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000015 (ops 71-75)
I20260812 06:18:27.033937  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000016 (ops 76-80)
I20260812 06:18:27.033962  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000017 (ops 81-85)
I20260812 06:18:27.033991  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000018 (ops 86-90)
I20260812 06:18:27.034021  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000019 (ops 91-94)
I20260812 06:18:27.034055  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000020 (ops 95-99)
I20260812 06:18:27.034088  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000021 (ops 100-104)
I20260812 06:18:27.034116  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000022 (ops 105-108)
I20260812 06:18:27.034137  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000023 (ops 109-113)
I20260812 06:18:27.034166  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000024 (ops 114-118)
I20260812 06:18:27.034190  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000025 (ops 119-123)
I20260812 06:18:27.034225  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000026 (ops 124-128)
I20260812 06:18:27.064339  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:27.064738  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91): 472 bytes on disk
I20260812 06:18:27.065330  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.065917  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:27.091688  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.025s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.092255  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:27.104663  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.105314  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:27.334475  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.229s	user 0.167s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":626,"lbm_read_time_us":16607,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38961,"lbm_writes_lt_1ms":743,"mutex_wait_us":275,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:18:27.334973  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=18.063937
I20260812 06:18:27.398175  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.063s	user 0.039s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":28622,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:27.398665  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:27.410771  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.412303  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:27.568756  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.156s	user 0.127s	sys 0.028s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":12659,"lbm_reads_lt_1ms":668,"lbm_write_time_us":31935,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31232,"update_count":3000}
I20260812 06:18:27.569515  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:27.621693  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.052s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.622270  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:27.639046  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.639586  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:27.814538  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.175s	user 0.118s	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":1323,"lbm_read_time_us":12377,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33795,"lbm_writes_lt_1ms":543,"mutex_wait_us":365,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:27.815249  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=12.110812
I20260812 06:18:27.854645  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.039s	user 0.013s	sys 0.023s Metrics: {"bytes_written":13825382,"delete_count":0,"lbm_write_time_us":16754,"lbm_writes_lt_1ms":340,"reinsert_count":0,"update_count":1685}
I20260812 06:18:27.855330  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.196750
I20260812 06:18:27.865461  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":3727,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:27.865924  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.019091  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.153s	user 0.109s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672239,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":8697,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26365,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:28.019850  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=11.118625
I20260812 06:18:28.059715  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17441,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.060537  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:28.078533  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.018s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.079113  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.222637  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.143s	user 0.115s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":8389,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26765,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:28.223398  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=10.126437
I20260812 06:18:28.263865  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.040s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.264472  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:28.277319  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.277993  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.410112  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.132s	user 0.091s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":7835,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27207,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:28.410955  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=10.126437
I20260812 06:18:28.451166  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.040s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17427,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.451802  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:28.467522  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.468394  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.496443  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushMRSOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.028s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1654,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1780,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:28.497149  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91): free 124257508 bytes of WAL
I20260812 06:18:28.497443  7570 log_reader.cc:385] T 6780aa5f03004ae2b7a246a0abf9ec91: removed 12 log segments from log reader
I20260812 06:18:28.497517  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000027 (ops 129-132)
I20260812 06:18:28.497577  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000028 (ops 133-137)
I20260812 06:18:28.497634  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000029 (ops 138-142)
I20260812 06:18:28.497679  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000030 (ops 143-147)
I20260812 06:18:28.497718  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000031 (ops 148-152)
I20260812 06:18:28.497757  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000032 (ops 153-157)
I20260812 06:18:28.497802  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000033 (ops 158-162)
I20260812 06:18:28.497841  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000034 (ops 163-167)
I20260812 06:18:28.497880  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000035 (ops 168-172)
I20260812 06:18:28.497920  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000036 (ops 173-177)
I20260812 06:18:28.497958  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000037 (ops 178-182)
I20260812 06:18:28.497996  7570 log.cc:1079] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: Deleting log segment in path: /tmp/dist-test-taskIgFLv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515497912383-7236-0/minicluster-data/ts-0-root/wals/6780aa5f03004ae2b7a246a0abf9ec91/wal-000000038 (ops 183-187)
I20260812 06:18:28.527092  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: LogGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:28.527647  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91): 463 bytes on disk
I20260812 06:18:28.528301  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: UndoDeltaBlockGCOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.528999  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=3.181125
I20260812 06:18:28.548352  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7428,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:28.548873  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:28.564703  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.565351  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.762686  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.197s	user 0.143s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":232,"lbm_read_time_us":14938,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37444,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26368,"thread_start_us":64,"threads_started":1,"update_count":3000}
I20260812 06:18:28.770004  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=14.095187
I20260812 06:18:28.824890  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.054s	user 0.042s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24030,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.825538  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=2.188937
I20260812 06:18:28.837924  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: FlushDeltaMemStoresOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.838761  7640 maintenance_manager.cc:419] P 4f55a84e4884459295ac45b2ff6f2438: Scheduling MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91): perf score=1.000000
I20260812 06:18:28.867084  7236 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.122s	user 1.870s	sys 0.198s
I20260812 06:18:28.925091  7236 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.002s	sys 0.000s
I20260812 06:18:28.925627  7236 tablet_server.cc:179] TabletServer@127.7.17.1:0 shutting down...
I20260812 06:18:28.972983  7570 maintenance_manager.cc:643] P 4f55a84e4884459295ac45b2ff6f2438: MajorDeltaCompactionOp(6780aa5f03004ae2b7a246a0abf9ec91) complete. Timing: real 0.134s	user 0.098s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":11215,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27314,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:28.973924  7236 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:28.974167  7236 tablet_replica.cc:333] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438: stopping tablet replica
I20260812 06:18:28.974301  7236 raft_consensus.cc:2243] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.974480  7236 raft_consensus.cc:2272] T 6780aa5f03004ae2b7a246a0abf9ec91 P 4f55a84e4884459295ac45b2ff6f2438 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.999730  7236 tablet_server.cc:196] TabletServer@127.7.17.1:0 shutdown complete.
I20260812 06:18:29.019845  7236 master.cc:562] Master@127.7.17.62:38131 shutting down...
I20260812 06:18:29.023689  7236 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.023923  7236 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.024008  7236 tablet_replica.cc:333] T 00000000000000000000000000000000 P 13b1d60b2227433d90b091e1c529e6ff: stopping tablet replica
I20260812 06:18:29.036650  7236 master.cc:584] Master@127.7.17.62:38131 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5576 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11203 ms total)

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