[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:40.407838  9315 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.24.254:35639
I20260812 06:16:40.408851  9315 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:40.409469  9315 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:40.416096  9315 server_base.cc:1061] running on GCE node
W20260812 06:16:40.416265  9320 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.416313  9324 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.416611  9321 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.417073  9315 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.417207  9315 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:40.417265  9315 hybrid_clock.cc:648] HybridClock initialized: now 1786515400417261 us; error 0 us; skew 500 ppm
I20260812 06:16:40.419082  9315 webserver.cc:533] Webserver started at http://127.9.24.254:40693/ using document root <none> and password file <none>
I20260812 06:16:40.419658  9315 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.419745  9315 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.420019  9315 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.421666  9315 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/master-0-root/instance:
uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-1xrh"
I20260812 06:16:40.425199  9315 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.003s
I20260812 06:16:40.427528  9329 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.428547  9315 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:16:40.428687  9315 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/master-0-root
uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-1xrh"
I20260812 06:16:40.428795  9315 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:40.441329  9315 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.442025  9315 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:40.442206  9315 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.450162  9315 rpc_server.cc:307] RPC server started. Bound to: 127.9.24.254:35639
I20260812 06:16:40.450181  9387 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.24.254:35639 every 8 connection(s)
I20260812 06:16:40.452643  9388 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.458544  9388 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: Bootstrap starting.
I20260812 06:16:40.461196  9388 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.462169  9388 log.cc:826] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:40.464064  9388 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: No bootstrap required, opened a new log
I20260812 06:16:40.467067  9388 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER }
I20260812 06:16:40.467258  9388 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.467411  9388 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4b2e40bd3a8c4dd3bbf7873db6eb4d38, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.468159  9388 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [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: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER }
I20260812 06:16:40.468372  9388 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.468456  9388 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.468616  9388 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.469488  9388 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER }
I20260812 06:16:40.469983  9388 leader_election.cc:304] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [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: 4b2e40bd3a8c4dd3bbf7873db6eb4d38; no voters: 
I20260812 06:16:40.470372  9388 leader_election.cc:290] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.470516  9391 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.470760  9391 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 1 LEADER]: Becoming Leader. State: Replica: 4b2e40bd3a8c4dd3bbf7873db6eb4d38, State: Running, Role: LEADER
I20260812 06:16:40.471251  9391 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [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: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER }
I20260812 06:16:40.471573  9388 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.473019  9392 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER } }
I20260812 06:16:40.473160  9392 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.473302  9394 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4b2e40bd3a8c4dd3bbf7873db6eb4d38. Latest consensus state: current_term: 1 leader_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b2e40bd3a8c4dd3bbf7873db6eb4d38" member_type: VOTER } }
I20260812 06:16:40.473376  9394 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.473649  9402 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.475996  9402 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.476300  9315 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:40.480922  9402 catalog_manager.cc:1383] Generated new cluster ID: 6c370d1fda4f48a1a3f87ac1c3fda0cf
I20260812 06:16:40.480994  9402 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.496340  9402 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.497157  9402 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.505842  9402 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: Generated new TSK 0
I20260812 06:16:40.506418  9402 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:40.508697  9315 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.511284  9412 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:40.511323  9413 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.511423  9315 server_base.cc:1061] running on GCE node
W20260812 06:16:40.511502  9415 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:40.511736  9315 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.511780  9315 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:40.511794  9315 hybrid_clock.cc:648] HybridClock initialized: now 1786515400511795 us; error 0 us; skew 500 ppm
I20260812 06:16:40.512732  9315 webserver.cc:533] Webserver started at http://127.9.24.193:45347/ using document root <none> and password file <none>
I20260812 06:16:40.512923  9315 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.512971  9315 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.513060  9315 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.513450  9315 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/instance:
uuid: "a2367ebb89684db38aa890726aa5fc66"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-1xrh"
I20260812 06:16:40.514936  9315 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:40.516004  9421 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.516247  9315 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:40.516320  9315 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root
uuid: "a2367ebb89684db38aa890726aa5fc66"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-1xrh"
I20260812 06:16:40.516400  9315 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:40.521003  9315 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.521384  9315 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.521865  9315 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:40.522713  9315 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:40.522763  9315 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.522843  9315 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:40.522892  9315 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.529687  9315 rpc_server.cc:307] RPC server started. Bound to: 127.9.24.193:34843
I20260812 06:16:40.529888  9495 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.24.193:34843 every 8 connection(s)
I20260812 06:16:40.543085  9496 heartbeater.cc:344] Connected to a master server at 127.9.24.254:35639
I20260812 06:16:40.543411  9496 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:40.543874  9496 heartbeater.cc:507] Master 127.9.24.254:35639 requested a full tablet report, sending...
I20260812 06:16:40.545324  9346 ts_manager.cc:194] Registered new tserver with Master: a2367ebb89684db38aa890726aa5fc66 (127.9.24.193:34843)
I20260812 06:16:40.545648  9315 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015231878s
I20260812 06:16:40.546864  9346 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40584
I20260812 06:16:40.555302  9346 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40596:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:40.569937  9452 tablet_service.cc:1511] Processing CreateTablet for tablet 4ac7531097784141864b11757a58201b (DEFAULT_TABLE table=heavy-update-compaction-test [id=2a3f60ff9ed646758e17efb904a20222]), partition=
I20260812 06:16:40.570370  9452 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4ac7531097784141864b11757a58201b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.572803  9511 tablet_bootstrap.cc:492] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Bootstrap starting.
I20260812 06:16:40.574133  9511 tablet_bootstrap.cc:654] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.575551  9511 tablet_bootstrap.cc:492] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: No bootstrap required, opened a new log
I20260812 06:16:40.575683  9511 ts_tablet_manager.cc:1403] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:40.576236  9511 raft_consensus.cc:359] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2367ebb89684db38aa890726aa5fc66" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 34843 } }
I20260812 06:16:40.576380  9511 raft_consensus.cc:385] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.576478  9511 raft_consensus.cc:740] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a2367ebb89684db38aa890726aa5fc66, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.576675  9511 consensus_queue.cc:260] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [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: "a2367ebb89684db38aa890726aa5fc66" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 34843 } }
I20260812 06:16:40.576786  9511 raft_consensus.cc:399] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.576838  9511 raft_consensus.cc:493] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.576892  9511 raft_consensus.cc:3060] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.577910  9511 raft_consensus.cc:515] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2367ebb89684db38aa890726aa5fc66" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 34843 } }
I20260812 06:16:40.578068  9511 leader_election.cc:304] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [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: a2367ebb89684db38aa890726aa5fc66; no voters: 
I20260812 06:16:40.578293  9511 leader_election.cc:290] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.578425  9513 raft_consensus.cc:2804] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.578640  9511 ts_tablet_manager.cc:1434] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:40.578668  9513 raft_consensus.cc:697] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 1 LEADER]: Becoming Leader. State: Replica: a2367ebb89684db38aa890726aa5fc66, State: Running, Role: LEADER
I20260812 06:16:40.578872  9496 heartbeater.cc:499] Master 127.9.24.254:35639 was elected leader, sending a full tablet report...
I20260812 06:16:40.579113  9513 consensus_queue.cc:237] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [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: "a2367ebb89684db38aa890726aa5fc66" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 34843 } }
I20260812 06:16:40.581835  9346 catalog_manager.cc:5719] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 reported cstate change: term changed from 0 to 1, leader changed from <none> to a2367ebb89684db38aa890726aa5fc66 (127.9.24.193). New cstate: current_term: 1 leader_uuid: "a2367ebb89684db38aa890726aa5fc66" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2367ebb89684db38aa890726aa5fc66" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 34843 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:40.651022  9315 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.015s	sys 0.012s
I20260812 06:16:40.780892  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushMRSOp(4ac7531097784141864b11757a58201b): perf score=15.086190
I20260812 06:16:40.944695  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushMRSOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.163s	user 0.122s	sys 0.040s Metrics: {"bytes_written":12840816,"cfile_init":1,"compiler_manager_pool.queue_time_us":186,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1015,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40941,"lbm_writes_lt_1ms":680,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":199936,"thread_start_us":113,"threads_started":1,"update_count":1565}
I20260812 06:16:40.945835  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling LogGCOp(4ac7531097784141864b11757a58201b): free 20743880 bytes of WAL
I20260812 06:16:40.946125  9426 log_reader.cc:385] T 4ac7531097784141864b11757a58201b: removed 2 log segments from log reader
I20260812 06:16:40.946185  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000001 (ops 1-6)
I20260812 06:16:40.946240  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000002 (ops 7-11)
I20260812 06:16:40.952116  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: LogGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:40.952433  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=5.165500
I20260812 06:16:40.975939  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.023s	user 0.013s	sys 0.009s Metrics: {"bytes_written":7261528,"delete_count":0,"lbm_write_time_us":10287,"lbm_writes_lt_1ms":180,"reinsert_count":0,"update_count":885}
I20260812 06:16:40.976432  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:41.159667  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.183s	user 0.118s	sys 0.061s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24364466,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":493,"lbm_read_time_us":11114,"lbm_reads_lt_1ms":558,"lbm_write_time_us":34064,"lbm_writes_lt_1ms":533,"mutex_wait_us":48,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":312,"threads_started":5,"update_count":2450}
I20260812 06:16:41.160362  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b): 12719217 bytes on disk
I20260812 06:16:41.160998  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.161482  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=11.118625
I20260812 06:16:41.201648  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.040s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17727,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:41.202201  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:41.213621  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4003,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.214099  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:41.342428  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1246,"lbm_read_time_us":9609,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24866,"lbm_writes_lt_1ms":443,"mutex_wait_us":379,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:41.343096  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:41.384263  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.041s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15756,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.384711  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:41.395164  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.395684  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:41.542145  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.146s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":185,"lbm_read_time_us":10955,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29379,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:16:41.542948  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:41.596827  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.054s	user 0.022s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18671,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.597371  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:41.608181  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.608639  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:41.761648  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.153s	user 0.097s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":12009,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24694,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:16:41.762423  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:41.812186  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16985,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.812667  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:41.824750  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.825476  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:41.946678  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":691,"lbm_read_time_us":8975,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23934,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:16:41.947247  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:41.985549  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.038s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15069,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.986020  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:41.997611  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.998075  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:42.123852  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.126s	user 0.078s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":10065,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26264,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:16:42.124579  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:42.175738  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.176403  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:42.193580  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.194219  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushMRSOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:42.238291  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushMRSOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.044s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1523,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1617,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:42.239351  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling LogGCOp(4ac7531097784141864b11757a58201b): free 112239276 bytes of WAL
I20260812 06:16:42.239611  9426 log_reader.cc:385] T 4ac7531097784141864b11757a58201b: removed 11 log segments from log reader
I20260812 06:16:42.239682  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000003 (ops 12-16)
I20260812 06:16:42.239737  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000004 (ops 17-21)
I20260812 06:16:42.239794  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000005 (ops 22-26)
I20260812 06:16:42.239836  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000006 (ops 27-30)
I20260812 06:16:42.239872  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000007 (ops 31-35)
I20260812 06:16:42.239912  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000008 (ops 36-40)
I20260812 06:16:42.239949  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000009 (ops 41-45)
I20260812 06:16:42.239986  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000010 (ops 46-50)
I20260812 06:16:42.240022  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000011 (ops 51-55)
I20260812 06:16:42.240058  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000012 (ops 56-60)
I20260812 06:16:42.240094  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000013 (ops 61-65)
I20260812 06:16:42.266706  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: LogGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:42.267210  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b): 445 bytes on disk
I20260812 06:16:42.267710  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.268273  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=3.181125
I20260812 06:16:42.283036  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:42.283500  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:42.293010  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.293491  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:42.511592  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.218s	user 0.145s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":467,"lbm_read_time_us":15228,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37579,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:16:42.513659  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:42.563932  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22412,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.564468  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:42.712867  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.148s	user 0.096s	sys 0.046s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":179,"lbm_read_time_us":10287,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25483,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:42.713526  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:42.768893  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.055s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22184,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.769438  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:42.782693  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.783337  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:42.972860  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.189s	user 0.129s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":12691,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31473,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:16:42.973457  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:43.027072  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.053s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.027608  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:43.046419  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.046974  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:43.195251  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.148s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1032,"lbm_read_time_us":10370,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28389,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:16:43.195755  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=11.118625
I20260812 06:16:43.234392  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.038s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717825,"delete_count":0,"lbm_write_time_us":17038,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.235172  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:43.255280  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.020s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5609,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.255803  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:43.388535  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.133s	user 0.090s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672358,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":9999,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26583,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:43.389550  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=10.126437
I20260812 06:16:43.437541  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.048s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17649,"lbm_writes_lt_1ms":303,"mutex_wait_us":1,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.438102  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:43.449533  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.450196  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:43.589962  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.140s	user 0.109s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1689,"lbm_read_time_us":10434,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25325,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:43.590703  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=11.118625
I20260812 06:16:43.637503  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.047s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15568,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:43.638191  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:43.652757  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5259,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.653290  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushMRSOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:43.680135  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushMRSOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.027s	user 0.020s	sys 0.006s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1507,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1769,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:43.680826  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling LogGCOp(4ac7531097784141864b11757a58201b): free 116849572 bytes of WAL
I20260812 06:16:43.681049  9426 log_reader.cc:385] T 4ac7531097784141864b11757a58201b: removed 12 log segments from log reader
I20260812 06:16:43.681110  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000014 (ops 66-70)
I20260812 06:16:43.681166  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000015 (ops 71-74)
I20260812 06:16:43.681224  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000016 (ops 75-79)
I20260812 06:16:43.681267  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000017 (ops 80-84)
I20260812 06:16:43.681308  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000018 (ops 85-88)
I20260812 06:16:43.681348  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000019 (ops 89-93)
I20260812 06:16:43.681387  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000020 (ops 94-98)
I20260812 06:16:43.681428  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000021 (ops 99-103)
I20260812 06:16:43.681468  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000022 (ops 104-108)
I20260812 06:16:43.681507  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000023 (ops 109-112)
I20260812 06:16:43.681548  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000024 (ops 113-117)
I20260812 06:16:43.681588  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000025 (ops 118-122)
I20260812 06:16:43.710875  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: LogGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:43.711385  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=3.181125
I20260812 06:16:43.731277  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7731,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:43.731755  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:43.741988  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.742520  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:43.950090  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.207s	user 0.123s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":139,"lbm_read_time_us":14774,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36234,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20992,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:16:43.951547  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b): 463 bytes on disk
I20260812 06:16:43.953326  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.954180  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:44.016709  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.062s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24061,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.017202  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:44.028676  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.029119  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:44.198858  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.170s	user 0.097s	sys 0.072s 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":692,"lbm_read_time_us":12043,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31668,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2500}
I20260812 06:16:44.199476  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:44.263295  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.064s	user 0.037s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24157,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":31360,"update_count":2000}
I20260812 06:16:44.263830  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:44.274629  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.275045  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:44.452069  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.177s	user 0.111s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":13874,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32024,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:16:44.452742  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=11.118625
I20260812 06:16:44.483783  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.031s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14075,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:44.484738  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:44.507833  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5567,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.508499  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:44.673045  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.164s	user 0.099s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":11643,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26392,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:44.673808  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:44.728467  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.054s	user 0.018s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25228,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.729010  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:44.741951  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.742466  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:44.907987  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.165s	user 0.126s	sys 0.032s 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":442,"lbm_read_time_us":9993,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32536,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.908710  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:44.970445  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.062s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":31017,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.970965  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:44.988046  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.017s	user 0.014s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.988739  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:45.144037  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.155s	user 0.123s	sys 0.029s 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":313,"lbm_read_time_us":11576,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31552,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:16:45.144814  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=14.095187
I20260812 06:16:45.218662  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.074s	user 0.041s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":41101,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:45.219241  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:45.233357  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.233865  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushMRSOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:45.266606  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushMRSOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.033s	user 0.023s	sys 0.007s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2955,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:45.267635  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling LogGCOp(4ac7531097784141864b11757a58201b): free 132571506 bytes of WAL
I20260812 06:16:45.267973  9426 log_reader.cc:385] T 4ac7531097784141864b11757a58201b: removed 13 log segments from log reader
I20260812 06:16:45.268042  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000026 (ops 123-127)
I20260812 06:16:45.268083  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000027 (ops 128-132)
I20260812 06:16:45.268150  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000028 (ops 133-137)
I20260812 06:16:45.268188  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000029 (ops 138-142)
I20260812 06:16:45.268225  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000030 (ops 143-146)
I20260812 06:16:45.268257  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000031 (ops 147-151)
I20260812 06:16:45.268291  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000032 (ops 152-156)
I20260812 06:16:45.268338  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000033 (ops 157-161)
I20260812 06:16:45.268386  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000034 (ops 162-166)
I20260812 06:16:45.268450  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000035 (ops 167-171)
I20260812 06:16:45.268484  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000036 (ops 172-176)
I20260812 06:16:45.268529  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000037 (ops 177-180)
I20260812 06:16:45.268572  9426 log.cc:1079] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/4ac7531097784141864b11757a58201b/wal-000000038 (ops 181-185)
I20260812 06:16:45.297827  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: LogGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:45.298280  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=6.157687
I20260812 06:16:45.337816  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.039s	user 0.018s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11684,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:45.338346  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:45.349732  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.350337  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b): 472 bytes on disk
I20260812 06:16:45.350857  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: UndoDeltaBlockGCOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.351509  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:45.573979  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.222s	user 0.164s	sys 0.052s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082164,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":513,"lbm_read_time_us":17051,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44698,"lbm_writes_lt_1ms":843,"mutex_wait_us":44,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":76,"threads_started":1,"update_count":4000}
I20260812 06:16:45.574766  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=18.063937
I20260812 06:16:45.635358  9315 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.984s	user 1.777s	sys 0.189s
I20260812 06:16:45.641309  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.066s	user 0.040s	sys 0.024s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":29794,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.641840  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b): perf score=2.188937
I20260812 06:16:45.658562  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: FlushDeltaMemStoresOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":500}
I20260812 06:16:45.659102  9498 maintenance_manager.cc:419] P a2367ebb89684db38aa890726aa5fc66: Scheduling MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b): perf score=1.000000
I20260812 06:16:45.708375  9315 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.002s	sys 0.000s
I20260812 06:16:45.709026  9315 tablet_server.cc:179] TabletServer@127.9.24.193:0 shutting down...
I20260812 06:16:45.832943  9426 maintenance_manager.cc:643] P a2367ebb89684db38aa890726aa5fc66: MajorDeltaCompactionOp(4ac7531097784141864b11757a58201b) complete. Timing: real 0.174s	user 0.101s	sys 0.071s Metrics: {"cfile_cache_hit":433,"cfile_cache_hit_bytes":17723437,"cfile_cache_miss":199,"cfile_cache_miss_bytes":11153669,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":507,"lbm_read_time_us":6079,"lbm_reads_lt_1ms":231,"lbm_write_time_us":53316,"lbm_writes_1-10_ms":12,"lbm_writes_lt_1ms":631,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":96256,"update_count":3000}
I20260812 06:16:45.833868  9315 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.834347  9315 tablet_replica.cc:333] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66: stopping tablet replica
I20260812 06:16:45.834631  9315 raft_consensus.cc:2243] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.834892  9315 raft_consensus.cc:2272] T 4ac7531097784141864b11757a58201b P a2367ebb89684db38aa890726aa5fc66 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.850975  9315 tablet_server.cc:196] TabletServer@127.9.24.193:0 shutdown complete.
I20260812 06:16:45.886217  9315 master.cc:562] Master@127.9.24.254:35639 shutting down...
I20260812 06:16:45.889714  9315 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.889878  9315 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.889946  9315 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4b2e40bd3a8c4dd3bbf7873db6eb4d38: stopping tablet replica
I20260812 06:16:45.902347  9315 master.cc:584] Master@127.9.24.254:35639 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5592 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:45.999848  9315 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.24.254:44193
I20260812 06:16:46.000211  9315 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.002251  9531 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:46.002332  9530 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:46.002401  9315 server_base.cc:1061] running on GCE node
W20260812 06:16:46.002537  9533 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:46.002722  9315 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.002768  9315 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:46.002818  9315 hybrid_clock.cc:648] HybridClock initialized: now 1786515406002817 us; error 0 us; skew 500 ppm
I20260812 06:16:46.003876  9315 webserver.cc:533] Webserver started at http://127.9.24.254:39941/ using document root <none> and password file <none>
I20260812 06:16:46.004071  9315 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.004140  9315 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.004227  9315 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.004628  9315 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/master-0-root/instance:
uuid: "57c9f506596440d8a5c9acfdc641a8ff"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-1xrh"
I20260812 06:16:46.006248  9315 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:46.007257  9538 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.007548  9315 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:46.007637  9315 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/master-0-root
uuid: "57c9f506596440d8a5c9acfdc641a8ff"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-1xrh"
I20260812 06:16:46.007731  9315 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:46.025637  9315 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.026095  9315 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.030655  9315 rpc_server.cc:307] RPC server started. Bound to: 127.9.24.254:44193
I20260812 06:16:46.036528  9599 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.24.254:44193 every 8 connection(s)
I20260812 06:16:46.042330  9600 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:46.044359  9600 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff: Bootstrap starting.
I20260812 06:16:46.045151  9600 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.046187  9600 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff: No bootstrap required, opened a new log
I20260812 06:16:46.046685  9600 raft_consensus.cc:359] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER }
I20260812 06:16:46.046772  9600 raft_consensus.cc:385] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.046794  9600 raft_consensus.cc:740] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 57c9f506596440d8a5c9acfdc641a8ff, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.046911  9600 consensus_queue.cc:260] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [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: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER }
I20260812 06:16:46.046969  9600 raft_consensus.cc:399] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.046993  9600 raft_consensus.cc:493] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.047021  9600 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.086882  9600 raft_consensus.cc:515] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER }
I20260812 06:16:46.087190  9600 leader_election.cc:304] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [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: 57c9f506596440d8a5c9acfdc641a8ff; no voters: 
I20260812 06:16:46.087498  9600 leader_election.cc:290] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.087697  9603 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.087965  9603 raft_consensus.cc:697] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 1 LEADER]: Becoming Leader. State: Replica: 57c9f506596440d8a5c9acfdc641a8ff, State: Running, Role: LEADER
I20260812 06:16:46.088186  9603 consensus_queue.cc:237] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [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: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER }
I20260812 06:16:46.088344  9600 sys_catalog.cc:565] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:46.088687  9603 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [sys.catalog]: SysCatalogTable state changed. Reason: New leader 57c9f506596440d8a5c9acfdc641a8ff. Latest consensus state: current_term: 1 leader_uuid: "57c9f506596440d8a5c9acfdc641a8ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER } }
I20260812 06:16:46.088959  9603 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.088863  9605 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "57c9f506596440d8a5c9acfdc641a8ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57c9f506596440d8a5c9acfdc641a8ff" member_type: VOTER } }
I20260812 06:16:46.089495  9605 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:46.089843  9607 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:46.090693  9607 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:46.091113  9315 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:46.092805  9607 catalog_manager.cc:1383] Generated new cluster ID: 5252c61d65c94019870ead490583528b
I20260812 06:16:46.092875  9607 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:46.101436  9607 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:46.101999  9607 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:46.109314  9607 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff: Generated new TSK 0
I20260812 06:16:46.109488  9607 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:46.123585  9315 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:46.125751  9623 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:46.125849  9626 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:46.125886  9315 server_base.cc:1061] running on GCE node
W20260812 06:16:46.125869  9624 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:46.126204  9315 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:46.126250  9315 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:46.126266  9315 hybrid_clock.cc:648] HybridClock initialized: now 1786515406126267 us; error 0 us; skew 500 ppm
I20260812 06:16:46.127159  9315 webserver.cc:533] Webserver started at http://127.9.24.193:45205/ using document root <none> and password file <none>
I20260812 06:16:46.127327  9315 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:46.127368  9315 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:46.127422  9315 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:46.127763  9315 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/instance:
uuid: "3c73dd7892194351a7879a628e626880"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-1xrh"
I20260812 06:16:46.129145  9315 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:46.130097  9631 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.130364  9315 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:46.130440  9315 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root
uuid: "3c73dd7892194351a7879a628e626880"
format_stamp: "Formatted at 2026-08-12 06:16:46 on dist-test-slave-1xrh"
I20260812 06:16:46.130488  9315 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:46.155512  9315 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:46.155912  9315 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:46.156252  9315 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:46.157212  9315 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:46.157269  9315 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.157326  9315 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:46.157368  9315 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:46.162614  9315 rpc_server.cc:307] RPC server started. Bound to: 127.9.24.193:39887
I20260812 06:16:46.163838  9707 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.24.193:39887 every 8 connection(s)
I20260812 06:16:46.172745  9708 heartbeater.cc:344] Connected to a master server at 127.9.24.254:44193
I20260812 06:16:46.172916  9708 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:46.173205  9708 heartbeater.cc:507] Master 127.9.24.254:44193 requested a full tablet report, sending...
I20260812 06:16:46.174086  9560 ts_manager.cc:194] Registered new tserver with Master: 3c73dd7892194351a7879a628e626880 (127.9.24.193:39887)
I20260812 06:16:46.174939  9315 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011372182s
I20260812 06:16:46.175230  9560 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43462
I20260812 06:16:46.186174  9560 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43470:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:46.203377  9662 tablet_service.cc:1511] Processing CreateTablet for tablet 66e65999a3ea45798f73d982601e795c (DEFAULT_TABLE table=heavy-update-compaction-test [id=5a025c7b2f994ea3a99e2773a277b9bb]), partition=
I20260812 06:16:46.203913  9662 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 66e65999a3ea45798f73d982601e795c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:46.205957  9723 tablet_bootstrap.cc:492] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Bootstrap starting.
I20260812 06:16:46.207280  9723 tablet_bootstrap.cc:654] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:46.208658  9723 tablet_bootstrap.cc:492] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: No bootstrap required, opened a new log
I20260812 06:16:46.208773  9723 ts_tablet_manager.cc:1403] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:46.209403  9723 raft_consensus.cc:359] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c73dd7892194351a7879a628e626880" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 39887 } }
I20260812 06:16:46.209535  9723 raft_consensus.cc:385] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:46.209589  9723 raft_consensus.cc:740] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c73dd7892194351a7879a628e626880, State: Initialized, Role: FOLLOWER
I20260812 06:16:46.209764  9723 consensus_queue.cc:260] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [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: "3c73dd7892194351a7879a628e626880" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 39887 } }
I20260812 06:16:46.209893  9723 raft_consensus.cc:399] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:46.209945  9723 raft_consensus.cc:493] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:46.210011  9723 raft_consensus.cc:3060] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:46.296379  9723 raft_consensus.cc:515] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c73dd7892194351a7879a628e626880" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 39887 } }
I20260812 06:16:46.296634  9723 leader_election.cc:304] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [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: 3c73dd7892194351a7879a628e626880; no voters: 
I20260812 06:16:46.296900  9723 leader_election.cc:290] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:46.297183  9725 raft_consensus.cc:2804] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:46.297328  9723 ts_tablet_manager.cc:1434] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Time spent starting tablet: real 0.088s	user 0.000s	sys 0.004s
I20260812 06:16:46.297344  9725 raft_consensus.cc:697] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 1 LEADER]: Becoming Leader. State: Replica: 3c73dd7892194351a7879a628e626880, State: Running, Role: LEADER
I20260812 06:16:46.297412  9708 heartbeater.cc:499] Master 127.9.24.254:44193 was elected leader, sending a full tablet report...
I20260812 06:16:46.297597  9725 consensus_queue.cc:237] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [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: "3c73dd7892194351a7879a628e626880" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 39887 } }
I20260812 06:16:46.299407  9560 catalog_manager.cc:5719] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3c73dd7892194351a7879a628e626880 (127.9.24.193). New cstate: current_term: 1 leader_uuid: "3c73dd7892194351a7879a628e626880" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c73dd7892194351a7879a628e626880" member_type: VOTER last_known_addr { host: "127.9.24.193" port: 39887 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:46.373685  9315 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.014s	sys 0.011s
I20260812 06:16:46.415020  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushMRSOp(66e65999a3ea45798f73d982601e795c): perf score=6.156503
I20260812 06:16:46.610664  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushMRSOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.195s	user 0.058s	sys 0.036s Metrics: {"bytes_written":4964175,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":335,"dirs.run_wall_time_us":21633,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":19617,"lbm_writes_lt_1ms":278,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"update_count":605}
I20260812 06:16:46.611409  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=10.126437
I20260812 06:16:46.715539  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.104s	user 0.016s	sys 0.021s Metrics: {"bytes_written":11445994,"delete_count":0,"lbm_write_time_us":15595,"lbm_writes_lt_1ms":282,"reinsert_count":0,"update_count":1395}
I20260812 06:16:46.716143  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:46.819098  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.103s	user 0.006s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8537,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:46.819919  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c): 4103815 bytes on disk
I20260812 06:16:46.820514  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.821154  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:46.923549  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.102s	user 0.014s	sys 0.019s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13453,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:46.924178  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.028739  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.104s	user 0.022s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12588,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":1000}
I20260812 06:16:47.029374  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.134697  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.104s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10872,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.135380  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.233989  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.098s	user 0.023s	sys 0.002s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11224,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.234678  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.337653  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.103s	user 0.013s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9286,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.338523  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.438947  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.100s	user 0.025s	sys 0.002s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12089,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.439684  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.532898  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.093s	user 0.017s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9738,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.533516  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=7.149875
I20260812 06:16:47.628718  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.095s	user 0.022s	sys 0.008s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":13082,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:47.629478  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:47.729055  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.099s	user 0.012s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8951,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.729668  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=9.134250
I20260812 06:16:47.828024  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.098s	user 0.022s	sys 0.008s Metrics: {"bytes_written":10543454,"delete_count":0,"lbm_write_time_us":13292,"lbm_writes_lt_1ms":260,"reinsert_count":0,"update_count":1285}
I20260812 06:16:47.828562  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=8.142062
I20260812 06:16:47.931543  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.103s	user 0.021s	sys 0.004s Metrics: {"bytes_written":9558878,"delete_count":0,"lbm_write_time_us":10451,"lbm_writes_lt_1ms":236,"reinsert_count":0,"update_count":1165}
I20260812 06:16:47.932231  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=7.149875
I20260812 06:16:48.036001  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.104s	user 0.018s	sys 0.009s Metrics: {"bytes_written":8410199,"delete_count":0,"lbm_write_time_us":12237,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1025}
I20260812 06:16:48.036696  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=10.126437
I20260812 06:16:48.141530  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.105s	user 0.017s	sys 0.020s Metrics: {"bytes_written":11979301,"delete_count":0,"lbm_write_time_us":15120,"lbm_writes_lt_1ms":295,"reinsert_count":0,"update_count":1460}
I20260812 06:16:48.142376  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=7.149875
I20260812 06:16:48.250542  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.108s	user 0.016s	sys 0.012s Metrics: {"bytes_written":8328155,"delete_count":0,"lbm_write_time_us":12447,"lbm_writes_lt_1ms":206,"reinsert_count":0,"update_count":1015}
I20260812 06:16:48.251329  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:48.354787  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.103s	user 0.017s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11659,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:48.355592  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=7.149875
I20260812 06:16:48.452980  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.097s	user 0.014s	sys 0.006s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9310,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:48.453609  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=7.149875
I20260812 06:16:48.555493  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.102s	user 0.022s	sys 0.004s Metrics: {"bytes_written":8533273,"delete_count":0,"lbm_write_time_us":10902,"lbm_writes_lt_1ms":211,"reinsert_count":0,"update_count":1040}
I20260812 06:16:48.556046  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=10.126437
I20260812 06:16:48.656353  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.100s	user 0.016s	sys 0.023s Metrics: {"bytes_written":11569067,"delete_count":0,"lbm_write_time_us":15378,"lbm_writes_lt_1ms":285,"reinsert_count":0,"update_count":1410}
I20260812 06:16:48.656939  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:48.687027  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.030s	user 0.007s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10766,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:48.687623  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushMRSOp(66e65999a3ea45798f73d982601e795c): perf score=1.000000
I20260812 06:16:48.743712  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushMRSOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.056s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1972184,"cfile_init":1,"dirs.queue_time_us":240,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1486,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2972,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":48,"thread_start_us":135,"threads_started":1}
I20260812 06:16:48.744431  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling LogGCOp(66e65999a3ea45798f73d982601e795c): free 203199427 bytes of WAL
I20260812 06:16:48.744733  9636 log_reader.cc:385] T 66e65999a3ea45798f73d982601e795c: removed 20 log segments from log reader
I20260812 06:16:48.744797  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000001 (ops 1-6)
I20260812 06:16:48.744845  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000002 (ops 7-10)
I20260812 06:16:48.744884  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000003 (ops 11-15)
I20260812 06:16:48.744908  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000004 (ops 16-20)
I20260812 06:16:48.744932  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000005 (ops 21-25)
I20260812 06:16:48.744962  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000006 (ops 26-30)
I20260812 06:16:48.744992  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000007 (ops 31-35)
I20260812 06:16:48.745028  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000008 (ops 36-40)
I20260812 06:16:48.745062  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000009 (ops 41-45)
I20260812 06:16:48.745091  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000010 (ops 46-50)
I20260812 06:16:48.745121  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000011 (ops 51-55)
I20260812 06:16:48.745147  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000012 (ops 56-60)
I20260812 06:16:48.745180  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000013 (ops 61-65)
I20260812 06:16:48.745214  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000014 (ops 66-70)
I20260812 06:16:48.745251  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000015 (ops 71-75)
I20260812 06:16:48.745280  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000016 (ops 76-80)
I20260812 06:16:48.745311  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000017 (ops 81-84)
I20260812 06:16:48.745345  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000018 (ops 85-89)
I20260812 06:16:48.745380  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000019 (ops 90-94)
I20260812 06:16:48.745412  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000020 (ops 95-98)
I20260812 06:16:48.796195  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: LogGCOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.052s	user 0.000s	sys 0.050s Metrics: {}
I20260812 06:16:48.796574  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=10.126437
I20260812 06:16:48.844779  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.048s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16363,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.845324  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c): 674 bytes on disk
I20260812 06:16:48.845743  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.846226  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=2.188937
I20260812 06:16:48.857863  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.858319  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling MajorDeltaCompactionOp(66e65999a3ea45798f73d982601e795c): perf score=1.000000
I20260812 06:16:51.516425  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: MajorDeltaCompactionOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 2.658s	user 1.078s	sys 1.579s Metrics: {"cfile_cache_miss":5154,"cfile_cache_miss_bytes":213365441,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":24,"delta_iterators_relevant":24,"dirs.queue_time_us":521,"lbm_read_time_us":95828,"lbm_reads_lt_1ms":5190,"lbm_write_time_us":957804,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":5144,"peak_mem_usage":634738212,"reinsert_count":0,"spinlock_wait_cycles":52096,"thread_start_us":461,"threads_started":7,"update_count":25500}
I20260812 06:16:51.517412  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=105.376437
I20260812 06:16:51.900713  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.383s	user 0.156s	sys 0.160s Metrics: {"bytes_written":110765515,"delete_count":0,"lbm_write_time_us":144936,"lbm_writes_lt_1ms":2705,"reinsert_count":0,"update_count":13500}
I20260812 06:16:51.901364  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=26.001437
I20260812 06:16:52.080894  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.179s	user 0.034s	sys 0.048s Metrics: {"bytes_written":28717136,"delete_count":0,"lbm_write_time_us":37333,"lbm_writes_lt_1ms":703,"reinsert_count":0,"update_count":3500}
I20260812 06:16:52.081667  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=10.126437
I20260812 06:16:52.294888  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.213s	user 0.016s	sys 0.036s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:52.295643  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=18.063937
I20260812 06:16:52.372870  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.077s	user 0.044s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":33518,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:52.373449  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=2.188937
I20260812 06:16:52.386312  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.386989  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushMRSOp(66e65999a3ea45798f73d982601e795c): perf score=1.000000
I20260812 06:16:52.420555  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushMRSOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1890246,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1373,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2215,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":46}
I20260812 06:16:52.421219  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling LogGCOp(66e65999a3ea45798f73d982601e795c): free 195832850 bytes of WAL
I20260812 06:16:52.421476  9636 log_reader.cc:385] T 66e65999a3ea45798f73d982601e795c: removed 19 log segments from log reader
I20260812 06:16:52.421522  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000021 (ops 99-103)
I20260812 06:16:52.421551  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000022 (ops 104-108)
I20260812 06:16:52.421571  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000023 (ops 109-113)
I20260812 06:16:52.421625  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000024 (ops 114-118)
I20260812 06:16:52.421674  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000025 (ops 119-123)
I20260812 06:16:52.421718  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000026 (ops 124-128)
I20260812 06:16:52.421774  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000027 (ops 129-133)
I20260812 06:16:52.421795  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000028 (ops 134-138)
I20260812 06:16:52.421850  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000029 (ops 139-143)
I20260812 06:16:52.421890  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000030 (ops 144-148)
I20260812 06:16:52.421940  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000031 (ops 149-153)
I20260812 06:16:52.421998  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000032 (ops 154-158)
I20260812 06:16:52.422041  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000033 (ops 159-163)
I20260812 06:16:52.422080  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000034 (ops 164-168)
I20260812 06:16:52.422123  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000035 (ops 169-173)
I20260812 06:16:52.422164  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000036 (ops 174-178)
I20260812 06:16:52.422204  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000037 (ops 179-183)
I20260812 06:16:52.422245  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000038 (ops 184-188)
I20260812 06:16:52.422283  9636 log.cc:1079] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: Deleting log segment in path: /tmp/dist-test-taskjFM8zy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400397360-9315-0/minicluster-data/ts-0-root/wals/66e65999a3ea45798f73d982601e795c/wal-000000039 (ops 189-193)
I20260812 06:16:52.467425  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: LogGCOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.046s	user 0.006s	sys 0.040s Metrics: {}
I20260812 06:16:52.468001  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c): 654 bytes on disk
I20260812 06:16:52.468595  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: UndoDeltaBlockGCOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.469328  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=6.157687
I20260812 06:16:52.496052  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.027s	user 0.017s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10952,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:52.496512  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c): perf score=2.188937
I20260812 06:16:52.507269  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: FlushDeltaMemStoresOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.507685  9709 maintenance_manager.cc:419] P 3c73dd7892194351a7879a628e626880: Scheduling MajorDeltaCompactionOp(66e65999a3ea45798f73d982601e795c): perf score=1.000000
I20260812 06:16:52.587539  9315 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.214s	user 1.777s	sys 0.222s
I20260812 06:16:53.019460  9315 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.431s	user 0.002s	sys 0.000s
I20260812 06:16:53.019979  9315 tablet_server.cc:179] TabletServer@127.9.24.193:0 shutting down...
I20260812 06:16:54.030776  9636 maintenance_manager.cc:643] P 3c73dd7892194351a7879a628e626880: MajorDeltaCompactionOp(66e65999a3ea45798f73d982601e795c) complete. Timing: real 1.523s	user 0.606s	sys 0.916s Metrics: {"cfile_cache_miss":4639,"cfile_cache_miss_bytes":192851420,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":7,"delta_iterators_relevant":7,"dirs.queue_time_us":938,"lbm_read_time_us":85392,"lbm_reads_lt_1ms":4675,"lbm_write_time_us":348522,"lbm_writes_lt_1ms":4647,"peak_mem_usage":572605352,"reinsert_count":0,"spinlock_wait_cycles":1258752,"thread_start_us":557,"threads_started":8,"update_count":23000,"wal-append.queue_time_us":292}
I20260812 06:16:54.031944  9315 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:54.032317  9315 tablet_replica.cc:333] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880: stopping tablet replica
I20260812 06:16:54.032485  9315 raft_consensus.cc:2243] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.032687  9315 raft_consensus.cc:2272] T 66e65999a3ea45798f73d982601e795c P 3c73dd7892194351a7879a628e626880 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.049494  9315 tablet_server.cc:196] TabletServer@127.9.24.193:0 shutdown complete.
I20260812 06:16:54.749073  9315 master.cc:562] Master@127.9.24.254:44193 shutting down...
I20260812 06:16:54.752625  9315 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.752810  9315 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.752859  9315 tablet_replica.cc:333] T 00000000000000000000000000000000 P 57c9f506596440d8a5c9acfdc641a8ff: stopping tablet replica
I20260812 06:16:54.765636  9315 master.cc:584] Master@127.9.24.254:44193 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (8856 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (14450 ms total)

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