[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:52.679487 28317 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.167.126:42919
I20260812 06:18:52.680709 28317 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:52.681329 28317 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:52.688162 28323 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:52.688216 28322 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:52.688355 28317 server_base.cc:1061] running on GCE node
W20260812 06:18:52.688476 28325 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:52.689029 28317 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:52.689172 28317 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:52.689244 28317 hybrid_clock.cc:648] HybridClock initialized: now 1786515532689240 us; error 0 us; skew 500 ppm
I20260812 06:18:52.691269 28317 webserver.cc:533] Webserver started at http://127.27.167.126:34147/ using document root <none> and password file <none>
I20260812 06:18:52.691967 28317 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:52.692065 28317 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:52.692339 28317 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:52.694168 28317 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/master-0-root/instance:
uuid: "f636a3ca32784956907ca0fcad971547"
format_stamp: "Formatted at 2026-08-12 06:18:52 on dist-test-slave-mvvj"
I20260812 06:18:52.698222 28317 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:18:52.700814 28330 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.702204 28317 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:52.702373 28317 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/master-0-root
uuid: "f636a3ca32784956907ca0fcad971547"
format_stamp: "Formatted at 2026-08-12 06:18:52 on dist-test-slave-mvvj"
I20260812 06:18:52.702507 28317 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:52.730804 28317 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:52.731595 28317 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:52.731798 28317 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:52.740237 28317 rpc_server.cc:307] RPC server started. Bound to: 127.27.167.126:42919
I20260812 06:18:52.740288 28390 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.167.126:42919 every 8 connection(s)
I20260812 06:18:52.742612 28391 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:52.748512 28391 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: Bootstrap starting.
I20260812 06:18:52.751143 28391 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:52.752200 28391 log.cc:826] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:52.754130 28391 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: No bootstrap required, opened a new log
I20260812 06:18:52.757112 28391 raft_consensus.cc:359] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f636a3ca32784956907ca0fcad971547" member_type: VOTER }
I20260812 06:18:52.757292 28391 raft_consensus.cc:385] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:52.757381 28391 raft_consensus.cc:740] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f636a3ca32784956907ca0fcad971547, State: Initialized, Role: FOLLOWER
I20260812 06:18:52.758162 28391 consensus_queue.cc:260] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [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: "f636a3ca32784956907ca0fcad971547" member_type: VOTER }
I20260812 06:18:52.758389 28391 raft_consensus.cc:399] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:52.758471 28391 raft_consensus.cc:493] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:52.758654 28391 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:52.759594 28391 raft_consensus.cc:515] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f636a3ca32784956907ca0fcad971547" member_type: VOTER }
I20260812 06:18:52.760097 28391 leader_election.cc:304] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [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: f636a3ca32784956907ca0fcad971547; no voters: 
I20260812 06:18:52.760461 28391 leader_election.cc:290] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:52.760659 28394 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:52.760950 28394 raft_consensus.cc:697] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 1 LEADER]: Becoming Leader. State: Replica: f636a3ca32784956907ca0fcad971547, State: Running, Role: LEADER
I20260812 06:18:52.761368 28394 consensus_queue.cc:237] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [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: "f636a3ca32784956907ca0fcad971547" member_type: VOTER }
I20260812 06:18:52.761580 28391 sys_catalog.cc:565] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:52.763525 28395 sys_catalog.cc:455] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f636a3ca32784956907ca0fcad971547" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f636a3ca32784956907ca0fcad971547" member_type: VOTER } }
I20260812 06:18:52.763512 28396 sys_catalog.cc:455] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f636a3ca32784956907ca0fcad971547. Latest consensus state: current_term: 1 leader_uuid: "f636a3ca32784956907ca0fcad971547" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f636a3ca32784956907ca0fcad971547" member_type: VOTER } }
I20260812 06:18:52.763669 28395 sys_catalog.cc:458] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:52.763733 28396 sys_catalog.cc:458] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:52.764009 28317 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:52.764209 28411 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:52.766857 28411 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:52.772112 28411 catalog_manager.cc:1383] Generated new cluster ID: dd0d918c4d9f4d3dbee824a717b3eb06
I20260812 06:18:52.772199 28411 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:52.799427 28411 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:52.800518 28411 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:52.809128 28411 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: Generated new TSK 0
I20260812 06:18:52.809870 28411 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:52.829437 28317 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:52.832587 28418 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:52.832607 28420 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:52.832581 28417 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:52.833094 28317 server_base.cc:1061] running on GCE node
I20260812 06:18:52.833266 28317 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:52.833313 28317 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:52.833336 28317 hybrid_clock.cc:648] HybridClock initialized: now 1786515532833336 us; error 0 us; skew 500 ppm
I20260812 06:18:52.834371 28317 webserver.cc:533] Webserver started at http://127.27.167.65:38989/ using document root <none> and password file <none>
I20260812 06:18:52.834568 28317 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:52.834635 28317 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:52.834704 28317 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:52.835166 28317 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/instance:
uuid: "b6938048dc5f4baeaf9aa665cc299786"
format_stamp: "Formatted at 2026-08-12 06:18:52 on dist-test-slave-mvvj"
I20260812 06:18:52.837231 28317 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:52.838462 28425 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.838845 28317 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:52.838948 28317 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root
uuid: "b6938048dc5f4baeaf9aa665cc299786"
format_stamp: "Formatted at 2026-08-12 06:18:52 on dist-test-slave-mvvj"
I20260812 06:18:52.839066 28317 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:52.860186 28317 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:52.860680 28317 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:52.861248 28317 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:52.862110 28317 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:52.862187 28317 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.862265 28317 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:52.862319 28317 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:52.869551 28317 rpc_server.cc:307] RPC server started. Bound to: 127.27.167.65:33629
I20260812 06:18:52.869585 28499 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.167.65:33629 every 8 connection(s)
I20260812 06:18:52.884269 28500 heartbeater.cc:344] Connected to a master server at 127.27.167.126:42919
I20260812 06:18:52.884588 28500 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:52.885119 28500 heartbeater.cc:507] Master 127.27.167.126:42919 requested a full tablet report, sending...
I20260812 06:18:52.886662 28348 ts_manager.cc:194] Registered new tserver with Master: b6938048dc5f4baeaf9aa665cc299786 (127.27.167.65:33629)
I20260812 06:18:52.887033 28317 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016780708s
I20260812 06:18:52.888217 28348 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50650
I20260812 06:18:52.897064 28348 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50654:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:52.912997 28457 tablet_service.cc:1511] Processing CreateTablet for tablet 2eab13e2e99745e3a454e6e5327e4ba2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1f4e627459194aed8166ff6525023009]), partition=
I20260812 06:18:52.913568 28457 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2eab13e2e99745e3a454e6e5327e4ba2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:52.916328 28514 tablet_bootstrap.cc:492] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Bootstrap starting.
I20260812 06:18:52.917398 28514 tablet_bootstrap.cc:654] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:52.918665 28514 tablet_bootstrap.cc:492] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: No bootstrap required, opened a new log
I20260812 06:18:52.918807 28514 ts_tablet_manager.cc:1403] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:52.919283 28514 raft_consensus.cc:359] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6938048dc5f4baeaf9aa665cc299786" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 33629 } }
I20260812 06:18:52.919417 28514 raft_consensus.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:52.919468 28514 raft_consensus.cc:740] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b6938048dc5f4baeaf9aa665cc299786, State: Initialized, Role: FOLLOWER
I20260812 06:18:52.919637 28514 consensus_queue.cc:260] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [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: "b6938048dc5f4baeaf9aa665cc299786" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 33629 } }
I20260812 06:18:52.919771 28514 raft_consensus.cc:399] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:52.919823 28514 raft_consensus.cc:493] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:52.919900 28514 raft_consensus.cc:3060] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:52.920855 28514 raft_consensus.cc:515] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6938048dc5f4baeaf9aa665cc299786" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 33629 } }
I20260812 06:18:52.921029 28514 leader_election.cc:304] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [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: b6938048dc5f4baeaf9aa665cc299786; no voters: 
I20260812 06:18:52.921396 28514 leader_election.cc:290] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:52.921506 28516 raft_consensus.cc:2804] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:52.921726 28516 raft_consensus.cc:697] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 1 LEADER]: Becoming Leader. State: Replica: b6938048dc5f4baeaf9aa665cc299786, State: Running, Role: LEADER
I20260812 06:18:52.921881 28514 ts_tablet_manager.cc:1434] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:52.921942 28516 consensus_queue.cc:237] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [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: "b6938048dc5f4baeaf9aa665cc299786" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 33629 } }
I20260812 06:18:52.922093 28500 heartbeater.cc:499] Master 127.27.167.126:42919 was elected leader, sending a full tablet report...
I20260812 06:18:52.925338 28348 catalog_manager.cc:5719] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 reported cstate change: term changed from 0 to 1, leader changed from <none> to b6938048dc5f4baeaf9aa665cc299786 (127.27.167.65). New cstate: current_term: 1 leader_uuid: "b6938048dc5f4baeaf9aa665cc299786" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6938048dc5f4baeaf9aa665cc299786" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 33629 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:52.991179 28317 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.010s	sys 0.016s
I20260812 06:18:53.120867 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=15.086190
I20260812 06:18:53.298909 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.178s	user 0.139s	sys 0.032s Metrics: {"bytes_written":13292072,"cfile_init":1,"compiler_manager_pool.queue_time_us":289,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":858,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44355,"lbm_writes_lt_1ms":691,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":139904,"thread_start_us":199,"threads_started":1,"update_count":1620}
I20260812 06:18:53.300196 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2): 12719217 bytes on disk
I20260812 06:18:53.300904 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.301317 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:53.315955 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4225738,"delete_count":0,"lbm_write_time_us":5681,"lbm_writes_lt_1ms":106,"mutex_wait_us":160,"reinsert_count":0,"update_count":515}
I20260812 06:18:53.316450 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2): free 20743880 bytes of WAL
I20260812 06:18:53.316723 28431 log_reader.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2: removed 2 log segments from log reader
I20260812 06:18:53.316790 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000001 (ops 1-6)
I20260812 06:18:53.316841 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000002 (ops 7-11)
I20260812 06:18:53.322113 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:53.322536 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.196750
I20260812 06:18:53.332543 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":3554,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:53.333037 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:53.518397 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.185s	user 0.133s	sys 0.051s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364539,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":506,"lbm_read_time_us":11654,"lbm_reads_lt_1ms":559,"lbm_write_time_us":29859,"lbm_writes_lt_1ms":533,"mutex_wait_us":44,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":322,"threads_started":5,"update_count":2450}
I20260812 06:18:53.518903 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:53.573817 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.055s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.574357 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:53.585690 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.586383 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:53.732466 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.146s	user 0.122s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":8850,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29407,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:18:53.733191 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=11.118625
I20260812 06:18:53.768656 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15169,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:53.769164 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:53.786707 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4777,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.787184 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:53.797595 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.798089 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:53.944905 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.147s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":392,"lbm_read_time_us":8777,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32530,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:53.945547 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=11.118625
I20260812 06:18:53.989915 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17499,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:53.990536 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.001606 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.002130 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:54.131954 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.130s	user 0.095s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":966,"lbm_read_time_us":7965,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27218,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:18:54.132668 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:54.180984 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.048s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19191,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.181524 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.192384 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.192976 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:54.327800 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.135s	user 0.104s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":5940,"lbm_read_time_us":9151,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24317,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:18:54.328588 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=11.118625
I20260812 06:18:54.382411 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.051s	user 0.027s	sys 0.022s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19342,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:54.383020 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.411653 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.028s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4883,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.412215 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.422869 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.423321 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:54.608567 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.185s	user 0.124s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":778,"lbm_read_time_us":11559,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30486,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:54.609328 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:54.662782 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.053s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18723,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.663326 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.673971 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.674427 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:54.718498 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.044s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1396,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2059,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:54.719383 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2): free 124710322 bytes of WAL
I20260812 06:18:54.719623 28431 log_reader.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2: removed 12 log segments from log reader
I20260812 06:18:54.719666 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000003 (ops 12-16)
I20260812 06:18:54.719696 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000004 (ops 17-21)
I20260812 06:18:54.719755 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000005 (ops 22-26)
I20260812 06:18:54.719789 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000006 (ops 27-31)
I20260812 06:18:54.719874 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000007 (ops 32-36)
I20260812 06:18:54.719933 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000008 (ops 37-41)
I20260812 06:18:54.719977 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000009 (ops 42-46)
I20260812 06:18:54.720016 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000010 (ops 47-51)
I20260812 06:18:54.720055 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000011 (ops 52-56)
I20260812 06:18:54.720095 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000012 (ops 57-61)
I20260812 06:18:54.720135 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000013 (ops 62-66)
I20260812 06:18:54.720175 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000014 (ops 67-71)
I20260812 06:18:54.746179 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:54.746703 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2): 493 bytes on disk
I20260812 06:18:54.747241 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.747804 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=3.181125
I20260812 06:18:54.767107 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.019s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6834,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:54.767540 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:54.777899 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3780,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.778434 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:54.990818 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.212s	user 0.160s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":439,"lbm_read_time_us":14849,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37028,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":22528,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:18:54.991616 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:55.045699 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24404,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.046314 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:55.067690 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.021s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"mutex_wait_us":62,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.068224 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:55.079960 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.012s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.080554 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:55.249584 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.169s	user 0.128s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":799,"lbm_read_time_us":11602,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33879,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:18:55.250285 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:55.302718 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22003,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.303313 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:55.319415 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.320024 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:55.480970 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.161s	user 0.116s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":10280,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30505,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:55.481770 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:55.527520 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.046s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20513,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.528195 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:55.675102 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.147s	user 0.110s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":851,"lbm_read_time_us":10898,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23944,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:18:55.675997 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:55.709936 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.034s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14695,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.710428 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:55.723037 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.723806 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:55.845012 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.121s	user 0.076s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":7969,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23029,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2000}
I20260812 06:18:55.845695 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:55.894086 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.048s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16298,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.894662 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:55.905951 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.906699 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.031708 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.125s	user 0.089s	sys 0.036s 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":240,"lbm_read_time_us":7523,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25061,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:56.032331 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:56.072163 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.040s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15790,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.072710 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:56.085809 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.086314 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.119390 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1539,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:56.120307 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2): free 120553332 bytes of WAL
I20260812 06:18:56.120611 28431 log_reader.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2: removed 12 log segments from log reader
I20260812 06:18:56.120662 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000015 (ops 72-76)
I20260812 06:18:56.120693 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000016 (ops 77-80)
I20260812 06:18:56.120733 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000017 (ops 81-85)
I20260812 06:18:56.120779 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000018 (ops 86-90)
I20260812 06:18:56.120803 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000019 (ops 91-95)
I20260812 06:18:56.120843 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000020 (ops 96-100)
I20260812 06:18:56.120883 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000021 (ops 101-104)
I20260812 06:18:56.120908 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000022 (ops 105-109)
I20260812 06:18:56.120952 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000023 (ops 110-114)
I20260812 06:18:56.120992 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000024 (ops 115-119)
I20260812 06:18:56.121030 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000025 (ops 120-124)
I20260812 06:18:56.121068 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000026 (ops 125-129)
I20260812 06:18:56.145690 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:56.146154 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=3.181125
I20260812 06:18:56.159361 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4785,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:56.159987 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2): free 12018006 bytes of WAL
I20260812 06:18:56.160244 28431 log_reader.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2: removed 1 log segments from log reader
I20260812 06:18:56.160312 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000027 (ops 130-134)
I20260812 06:18:56.163177 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:56.163587 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:56.178684 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.179370 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.347450 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.168s	user 0.132s	sys 0.032s 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":701,"lbm_read_time_us":13296,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32656,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:56.348253 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=14.095187
I20260812 06:18:56.402561 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.053s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21172,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.403086 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2): 462 bytes on disk
I20260812 06:18:56.403517 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.404084 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:56.416855 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4351,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.417394 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.583904 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.166s	user 0.131s	sys 0.031s 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":289,"lbm_read_time_us":11045,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31913,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2500}
I20260812 06:18:56.584517 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=11.118625
I20260812 06:18:56.621600 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":13333099,"delete_count":0,"lbm_write_time_us":16069,"lbm_writes_lt_1ms":328,"reinsert_count":0,"update_count":1625}
I20260812 06:18:56.622294 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.196750
I20260812 06:18:56.633849 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:56.634320 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.771399 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.137s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672257,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":9183,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24198,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.772116 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:56.815218 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.043s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.815783 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:56.828238 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.828855 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:56.965723 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.137s	user 0.105s	sys 0.031s 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":819,"lbm_read_time_us":8285,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28402,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:56.966444 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:57.005357 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.039s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17861,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.005852 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.017711 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.018224 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:57.146034 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.128s	user 0.106s	sys 0.021s 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":787,"lbm_read_time_us":9241,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25298,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:57.146873 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:57.187331 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.040s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16408,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.187893 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.198532 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.199050 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:57.330802 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.132s	user 0.091s	sys 0.040s 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":1051,"lbm_read_time_us":9227,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25719,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:18:57.331387 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:57.386345 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.055s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14793,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.386895 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.397780 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.398257 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:57.543123 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.145s	user 0.094s	sys 0.049s 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":352,"lbm_read_time_us":10564,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24359,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.543737 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=10.126437
I20260812 06:18:57.589399 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.045s	user 0.016s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.589895 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.600986 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.601873 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:57.631439 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushMRSOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1360,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1746,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:57.632274 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2): free 116849774 bytes of WAL
I20260812 06:18:57.632561 28431 log_reader.cc:385] T 2eab13e2e99745e3a454e6e5327e4ba2: removed 12 log segments from log reader
I20260812 06:18:57.632624 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000028 (ops 135-139)
I20260812 06:18:57.632676 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000029 (ops 140-144)
I20260812 06:18:57.632709 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000030 (ops 145-148)
I20260812 06:18:57.632732 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000031 (ops 149-153)
I20260812 06:18:57.632754 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000032 (ops 154-158)
I20260812 06:18:57.632786 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000033 (ops 159-163)
I20260812 06:18:57.632820 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000034 (ops 164-168)
I20260812 06:18:57.632851 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000035 (ops 169-172)
I20260812 06:18:57.632881 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000036 (ops 173-177)
I20260812 06:18:57.632910 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000037 (ops 178-182)
I20260812 06:18:57.632939 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000038 (ops 183-186)
I20260812 06:18:57.632972 28431 log.cc:1079] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/2eab13e2e99745e3a454e6e5327e4ba2/wal-000000039 (ops 187-191)
I20260812 06:18:57.662361 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: LogGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:57.662846 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2): 484 bytes on disk
I20260812 06:18:57.663368 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: UndoDeltaBlockGCOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.664077 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.692191 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.028s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.692900 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=2.188937
I20260812 06:18:57.709219 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.709880 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=1.000000
I20260812 06:18:57.814071 28317 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.823s	user 1.837s	sys 0.111s
I20260812 06:18:57.892467 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: MajorDeltaCompactionOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.182s	user 0.138s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":524,"lbm_read_time_us":14626,"lbm_reads_lt_1ms":670,"lbm_write_time_us":30344,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:57.893239 28501 maintenance_manager.cc:419] P b6938048dc5f4baeaf9aa665cc299786: Scheduling FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2): perf score=6.157687
I20260812 06:18:57.900938 28317 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.003s	sys 0.000s
I20260812 06:18:57.901602 28317 tablet_server.cc:179] TabletServer@127.27.167.65:0 shutting down...
I20260812 06:18:57.919047 28431 maintenance_manager.cc:643] P b6938048dc5f4baeaf9aa665cc299786: FlushDeltaMemStoresOp(2eab13e2e99745e3a454e6e5327e4ba2) complete. Timing: real 0.026s	user 0.014s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10424,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:57.919804 28317 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:57.920240 28317 tablet_replica.cc:333] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786: stopping tablet replica
I20260812 06:18:57.920514 28317 raft_consensus.cc:2243] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:57.920768 28317 raft_consensus.cc:2272] T 2eab13e2e99745e3a454e6e5327e4ba2 P b6938048dc5f4baeaf9aa665cc299786 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:57.936312 28317 tablet_server.cc:196] TabletServer@127.27.167.65:0 shutdown complete.
I20260812 06:18:57.943519 28317 master.cc:562] Master@127.27.167.126:42919 shutting down...
I20260812 06:18:57.947471 28317 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:57.947674 28317 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:57.947767 28317 tablet_replica.cc:333] T 00000000000000000000000000000000 P f636a3ca32784956907ca0fcad971547: stopping tablet replica
I20260812 06:18:57.960418 28317 master.cc:584] Master@127.27.167.126:42919 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5370 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:58.061069 28317 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.167.126:36553
I20260812 06:18:58.061517 28317 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.063860 28534 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.063836 28535 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.063907 28317 server_base.cc:1061] running on GCE node
W20260812 06:18:58.063915 28537 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.064429 28317 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.064478 28317 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.064497 28317 hybrid_clock.cc:648] HybridClock initialized: now 1786515538064497 us; error 0 us; skew 500 ppm
I20260812 06:18:58.065382 28317 webserver.cc:533] Webserver started at http://127.27.167.126:43563/ using document root <none> and password file <none>
I20260812 06:18:58.065596 28317 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.065680 28317 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.065771 28317 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.066241 28317 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/master-0-root/instance:
uuid: "8df569d9a577492dbbc4a17cd00c1403"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-mvvj"
I20260812 06:18:58.067986 28317 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:58.069068 28543 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.069324 28317 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:58.069424 28317 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/master-0-root
uuid: "8df569d9a577492dbbc4a17cd00c1403"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-mvvj"
I20260812 06:18:58.069511 28317 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:58.078706 28317 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.079164 28317 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.084146 28317 rpc_server.cc:307] RPC server started. Bound to: 127.27.167.126:36553
I20260812 06:18:58.085781 28603 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.167.126:36553 every 8 connection(s)
I20260812 06:18:58.086638 28604 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.090945 28604 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403: Bootstrap starting.
I20260812 06:18:58.091989 28604 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.093156 28604 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403: No bootstrap required, opened a new log
I20260812 06:18:58.093694 28604 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER }
I20260812 06:18:58.093791 28604 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.093816 28604 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8df569d9a577492dbbc4a17cd00c1403, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.093991 28604 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [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: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER }
I20260812 06:18:58.094079 28604 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.094105 28604 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.094180 28604 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.094980 28604 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER }
I20260812 06:18:58.095165 28604 leader_election.cc:304] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [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: 8df569d9a577492dbbc4a17cd00c1403; no voters: 
I20260812 06:18:58.095445 28604 leader_election.cc:290] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.095513 28607 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.095799 28607 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 1 LEADER]: Becoming Leader. State: Replica: 8df569d9a577492dbbc4a17cd00c1403, State: Running, Role: LEADER
I20260812 06:18:58.096014 28607 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [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: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER }
I20260812 06:18:58.096063 28604 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:58.096550 28608 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8df569d9a577492dbbc4a17cd00c1403" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER } }
I20260812 06:18:58.096575 28609 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8df569d9a577492dbbc4a17cd00c1403. Latest consensus state: current_term: 1 leader_uuid: "8df569d9a577492dbbc4a17cd00c1403" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8df569d9a577492dbbc4a17cd00c1403" member_type: VOTER } }
I20260812 06:18:58.096737 28608 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.096768 28609 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.097229 28612 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:58.098011 28612 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:58.098259 28317 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:58.100124 28612 catalog_manager.cc:1383] Generated new cluster ID: 8850795a65ac42088c21e2aa7c7542ab
I20260812 06:18:58.100191 28612 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:58.124780 28612 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:58.125752 28612 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:58.135521 28612 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403: Generated new TSK 0
I20260812 06:18:58.135751 28612 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:58.163136 28317 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.165653 28626 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.165678 28629 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.165694 28625 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.166023 28317 server_base.cc:1061] running on GCE node
I20260812 06:18:58.166244 28317 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.166342 28317 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.166424 28317 hybrid_clock.cc:648] HybridClock initialized: now 1786515538166415 us; error 0 us; skew 500 ppm
I20260812 06:18:58.167451 28317 webserver.cc:533] Webserver started at http://127.27.167.65:41075/ using document root <none> and password file <none>
I20260812 06:18:58.167630 28317 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.167682 28317 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.167794 28317 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.168259 28317 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/instance:
uuid: "28b0ac15567342229edb62e5d18b07d7"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-mvvj"
I20260812 06:18:58.169858 28317 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:58.170953 28634 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.171270 28317 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.171342 28317 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root
uuid: "28b0ac15567342229edb62e5d18b07d7"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-mvvj"
I20260812 06:18:58.171433 28317 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:58.184684 28317 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.185117 28317 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.185444 28317 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:58.185966 28317 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:58.186004 28317 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.186061 28317 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:58.186100 28317 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.190829 28317 rpc_server.cc:307] RPC server started. Bound to: 127.27.167.65:43979
I20260812 06:18:58.191315 28703 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.167.65:43979 every 8 connection(s)
I20260812 06:18:58.205705 28705 heartbeater.cc:344] Connected to a master server at 127.27.167.126:36553
I20260812 06:18:58.205855 28705 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:58.206161 28705 heartbeater.cc:507] Master 127.27.167.126:36553 requested a full tablet report, sending...
I20260812 06:18:58.206897 28562 ts_manager.cc:194] Registered new tserver with Master: 28b0ac15567342229edb62e5d18b07d7 (127.27.167.65:43979)
I20260812 06:18:58.207082 28317 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015562877s
I20260812 06:18:58.207965 28562 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41528
I20260812 06:18:58.215852 28562 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41534:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:58.227717 28664 tablet_service.cc:1511] Processing CreateTablet for tablet 28e6d4b6ae4f4aab96dcb5d87a1d5074 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1cdcb9c7a574033a467e704004a4973]), partition=
I20260812 06:18:58.228072 28664 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 28e6d4b6ae4f4aab96dcb5d87a1d5074. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.229977 28719 tablet_bootstrap.cc:492] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Bootstrap starting.
I20260812 06:18:58.230993 28719 tablet_bootstrap.cc:654] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.232157 28719 tablet_bootstrap.cc:492] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: No bootstrap required, opened a new log
I20260812 06:18:58.232249 28719 ts_tablet_manager.cc:1403] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:58.232693 28719 raft_consensus.cc:359] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b0ac15567342229edb62e5d18b07d7" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 43979 } }
I20260812 06:18:58.232788 28719 raft_consensus.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.232811 28719 raft_consensus.cc:740] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 28b0ac15567342229edb62e5d18b07d7, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.232952 28719 consensus_queue.cc:260] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [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: "28b0ac15567342229edb62e5d18b07d7" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 43979 } }
I20260812 06:18:58.233037 28719 raft_consensus.cc:399] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.233062 28719 raft_consensus.cc:493] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.233091 28719 raft_consensus.cc:3060] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.233909 28719 raft_consensus.cc:515] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b0ac15567342229edb62e5d18b07d7" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 43979 } }
I20260812 06:18:58.234059 28719 leader_election.cc:304] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [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: 28b0ac15567342229edb62e5d18b07d7; no voters: 
I20260812 06:18:58.234325 28719 leader_election.cc:290] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.234422 28722 raft_consensus.cc:2804] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.234597 28722 raft_consensus.cc:697] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 1 LEADER]: Becoming Leader. State: Replica: 28b0ac15567342229edb62e5d18b07d7, State: Running, Role: LEADER
I20260812 06:18:58.234684 28719 ts_tablet_manager.cc:1434] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:58.234727 28705 heartbeater.cc:499] Master 127.27.167.126:36553 was elected leader, sending a full tablet report...
I20260812 06:18:58.234741 28722 consensus_queue.cc:237] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [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: "28b0ac15567342229edb62e5d18b07d7" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 43979 } }
I20260812 06:18:58.236446 28562 catalog_manager.cc:5719] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 28b0ac15567342229edb62e5d18b07d7 (127.27.167.65). New cstate: current_term: 1 leader_uuid: "28b0ac15567342229edb62e5d18b07d7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "28b0ac15567342229edb62e5d18b07d7" member_type: VOTER last_known_addr { host: "127.27.167.65" port: 43979 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:58.298417 28317 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:18:58.442152 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=19.054940
I20260812 06:18:58.606841 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.164s	user 0.122s	sys 0.039s Metrics: {"bytes_written":12963883,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1033,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39845,"lbm_writes_lt_1ms":773,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":72576,"update_count":1580}
I20260812 06:18:58.607638 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): free 20743831 bytes of WAL
I20260812 06:18:58.607931 28639 log_reader.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074: removed 2 log segments from log reader
I20260812 06:18:58.607975 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000001 (ops 1-6)
I20260812 06:18:58.608028 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000002 (ops 7-11)
I20260812 06:18:58.613186 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:58.613627 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:58.631789 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.018s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3856514,"delete_count":0,"lbm_write_time_us":5654,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:58.632375 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:58.646183 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5202,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.646698 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:58.846627 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.200s	user 0.113s	sys 0.077s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":607,"lbm_read_time_us":14508,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27773,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":363,"threads_started":5,"update_count":2500}
I20260812 06:18:58.847332 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): 16411392 bytes on disk
I20260812 06:18:58.847945 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.848465 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=14.095187
I20260812 06:18:58.890481 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.042s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.891011 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:59.068311 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.177s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":143,"lbm_read_time_us":13387,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28152,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:18:59.068893 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=14.095187
I20260812 06:18:59.120728 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.052s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19302,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.121241 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.132711 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.010s	sys 0.000s 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:18:59.133178 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:59.328127 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.195s	user 0.135s	sys 0.046s 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":284,"lbm_read_time_us":12354,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28438,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:59.328822 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=14.095187
I20260812 06:18:59.379060 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.050s	user 0.030s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18550,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.379534 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.390818 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.391317 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:59.554677 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.163s	user 0.121s	sys 0.039s 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":1266,"lbm_read_time_us":11064,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31513,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:18:59.555621 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=11.118625
I20260812 06:18:59.588925 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.033s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14524,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.589493 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.616261 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.027s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5566,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.616796 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.627982 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.628487 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:59.781574 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.153s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1122,"lbm_read_time_us":10325,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30696,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:18:59.782181 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=11.118625
I20260812 06:18:59.814669 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.032s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13595,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.815296 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.841349 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5313,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.841837 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.852942 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.853467 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:18:59.887005 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":361,"dirs.run_wall_time_us":1666,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1955,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:59.887682 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): free 115943234 bytes of WAL
I20260812 06:18:59.887955 28639 log_reader.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074: removed 11 log segments from log reader
I20260812 06:18:59.888005 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000003 (ops 12-16)
I20260812 06:18:59.888036 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000004 (ops 17-21)
I20260812 06:18:59.888101 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000005 (ops 22-26)
I20260812 06:18:59.888142 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000006 (ops 27-31)
I20260812 06:18:59.888182 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000007 (ops 32-36)
I20260812 06:18:59.888222 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000008 (ops 37-41)
I20260812 06:18:59.888262 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000009 (ops 42-46)
I20260812 06:18:59.888301 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000010 (ops 47-51)
I20260812 06:18:59.888339 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000011 (ops 52-56)
I20260812 06:18:59.888381 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000012 (ops 57-61)
I20260812 06:18:59.888420 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000013 (ops 62-66)
I20260812 06:18:59.912721 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:59.913367 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=3.181125
I20260812 06:18:59.934357 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.021s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4307780,"delete_count":0,"lbm_write_time_us":6969,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:59.934844 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:18:59.954984 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3980,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:59.955549 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:00.196857 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.241s	user 0.150s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979857,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1058,"lbm_read_time_us":15860,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39511,"lbm_writes_lt_1ms":743,"mutex_wait_us":345,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:19:00.197402 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=18.063937
I20260812 06:19:00.264914 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.067s	user 0.033s	sys 0.026s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":25857,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:00.265441 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:00.278820 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.279448 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): 463 bytes on disk
I20260812 06:19:00.280052 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.280730 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:00.486193 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.205s	user 0.145s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":14100,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32228,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:19:00.487007 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=16.079562
I20260812 06:19:00.561213 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.074s	user 0.034s	sys 0.027s Metrics: {"bytes_written":17640627,"delete_count":0,"lbm_write_time_us":28608,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2150}
I20260812 06:19:00.561834 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=5.165500
I20260812 06:19:00.581882 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6974357,"delete_count":0,"lbm_write_time_us":8159,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:19:00.582418 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:00.789513 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.207s	user 0.112s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":14504,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31965,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:19:00.790226 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=18.063937
I20260812 06:19:00.870357 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.080s	user 0.038s	sys 0.036s Metrics: {"bytes_written":20512323,"delete_count":0,"lbm_write_time_us":34299,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:00.870954 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:00.882647 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.883414 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:01.106482 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.223s	user 0.163s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877110,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":16186,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36198,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1243136,"update_count":3000}
I20260812 06:19:01.107992 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=16.079562
I20260812 06:19:01.174876 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.067s	user 0.022s	sys 0.028s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":23530,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:19:01.175523 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=5.165500
I20260812 06:19:01.193224 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":6933333,"delete_count":0,"lbm_write_time_us":7132,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:19:01.193693 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:01.412858 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.219s	user 0.152s	sys 0.057s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":926,"lbm_read_time_us":13240,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35419,"lbm_writes_lt_1ms":643,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":3000}
I20260812 06:19:01.413676 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=18.063937
I20260812 06:19:01.483072 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.069s	user 0.030s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25563,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:01.483680 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:01.494234 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.494860 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:01.531076 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1409,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2094,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:01.531818 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): free 129773587 bytes of WAL
I20260812 06:19:01.532112 28639 log_reader.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074: removed 13 log segments from log reader
I20260812 06:19:01.532157 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000014 (ops 67-71)
I20260812 06:19:01.532207 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000015 (ops 72-76)
I20260812 06:19:01.532253 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000016 (ops 77-81)
I20260812 06:19:01.532285 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000017 (ops 82-86)
I20260812 06:19:01.532326 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000018 (ops 87-90)
I20260812 06:19:01.532367 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000019 (ops 91-95)
I20260812 06:19:01.532407 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000020 (ops 96-100)
I20260812 06:19:01.532446 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000021 (ops 101-105)
I20260812 06:19:01.532486 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000022 (ops 106-110)
I20260812 06:19:01.532531 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000023 (ops 111-115)
I20260812 06:19:01.532572 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000024 (ops 116-120)
I20260812 06:19:01.532618 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000025 (ops 121-125)
I20260812 06:19:01.532660 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000026 (ops 126-130)
I20260812 06:19:01.559942 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:01.560406 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): 492 bytes on disk
I20260812 06:19:01.561054 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.561648 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=3.181125
I20260812 06:19:01.580165 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.018s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7588,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:01.580612 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): free 11564893 bytes of WAL
I20260812 06:19:01.580816 28639 log_reader.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074: removed 1 log segments from log reader
I20260812 06:19:01.580858 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000027 (ops 131-134)
I20260812 06:19:01.583019 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:01.583305 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:01.593528 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3650,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.594148 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:01.844249 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.250s	user 0.127s	sys 0.117s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082152,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":779,"lbm_read_time_us":17627,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44089,"lbm_writes_lt_1ms":843,"mutex_wait_us":307,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":89,"threads_started":1,"update_count":4000}
I20260812 06:19:01.845113 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=19.056125
I20260812 06:19:01.908087 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.063s	user 0.034s	sys 0.028s Metrics: {"bytes_written":20922555,"delete_count":0,"lbm_write_time_us":27653,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:19:01.908658 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=6.157687
I20260812 06:19:01.929316 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.020s	user 0.014s	sys 0.005s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":8827,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:01.929848 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:02.125809 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.196s	user 0.133s	sys 0.061s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32979514,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":14396,"lbm_reads_lt_1ms":772,"lbm_write_time_us":38551,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":3500}
I20260812 06:19:02.126502 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=15.087375
I20260812 06:19:02.178999 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.052s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23033,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:02.179612 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:02.200104 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.020s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.200575 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:02.210836 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3802,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.211370 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:02.388234 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.177s	user 0.117s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":416,"lbm_read_time_us":14510,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33790,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":3000}
I20260812 06:19:02.388953 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=14.095187
I20260812 06:19:02.442484 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.053s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20392,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.443069 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:02.459052 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.459679 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:02.616259 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.156s	user 0.116s	sys 0.040s 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":134,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28668,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27136,"update_count":2500}
I20260812 06:19:02.616894 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=10.126437
I20260812 06:19:02.665591 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20213,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.666173 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:02.677820 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.678411 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:02.840263 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.162s	user 0.127s	sys 0.029s 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":795,"lbm_read_time_us":11238,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27294,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:02.841035 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=11.118625
I20260812 06:19:02.880036 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.039s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16482,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.880934 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:02.894418 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5212,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.895015 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:02.950860 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushMRSOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.056s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1535,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:02.951609 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=3.181125
I20260812 06:19:02.967285 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.967765 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): free 108988743 bytes of WAL
I20260812 06:19:02.968016 28639 log_reader.cc:385] T 28e6d4b6ae4f4aab96dcb5d87a1d5074: removed 11 log segments from log reader
I20260812 06:19:02.968079 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000028 (ops 135-139)
I20260812 06:19:02.968134 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000029 (ops 140-144)
I20260812 06:19:02.968191 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000030 (ops 145-148)
I20260812 06:19:02.968232 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000031 (ops 149-153)
I20260812 06:19:02.968269 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000032 (ops 154-158)
I20260812 06:19:02.968305 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000033 (ops 159-163)
I20260812 06:19:02.968348 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000034 (ops 164-168)
I20260812 06:19:02.968393 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000035 (ops 169-173)
I20260812 06:19:02.968436 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000036 (ops 174-178)
I20260812 06:19:02.968474 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000037 (ops 179-183)
I20260812 06:19:02.968510 28639 log.cc:1079] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: Deleting log segment in path: /tmp/dist-test-task4Vi_O4/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515532667912-28317-0/minicluster-data/ts-0-root/wals/28e6d4b6ae4f4aab96dcb5d87a1d5074/wal-000000038 (ops 184-188)
I20260812 06:19:02.992203 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: LogGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.024s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:02.992787 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): 463 bytes on disk
I20260812 06:19:02.993372 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: UndoDeltaBlockGCOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.993991 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:03.012173 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.018s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.012635 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=2.188937
I20260812 06:19:03.023141 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.023638 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:03.229399 28317 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.931s	user 1.807s	sys 0.156s
I20260812 06:19:03.265372 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.242s	user 0.194s	sys 0.046s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16678,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40838,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":3500}
I20260812 06:19:03.265929 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=14.095187
I20260812 06:19:03.299038 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: FlushDeltaMemStoresOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.033s	user 0.012s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.299533 28706 maintenance_manager.cc:419] P 28b0ac15567342229edb62e5d18b07d7: Scheduling MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074): perf score=1.000000
I20260812 06:19:03.353072 28317 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.123s	user 0.001s	sys 0.002s
I20260812 06:19:03.353624 28317 tablet_server.cc:179] TabletServer@127.27.167.65:0 shutting down...
I20260812 06:19:03.421481 28639 maintenance_manager.cc:643] P 28b0ac15567342229edb62e5d18b07d7: MajorDeltaCompactionOp(28e6d4b6ae4f4aab96dcb5d87a1d5074) complete. Timing: real 0.122s	user 0.106s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":703,"lbm_read_time_us":8968,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26177,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":136,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:19:03.422391 28317 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:03.422701 28317 tablet_replica.cc:333] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7: stopping tablet replica
I20260812 06:19:03.422904 28317 raft_consensus.cc:2243] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:03.423099 28317 raft_consensus.cc:2272] T 28e6d4b6ae4f4aab96dcb5d87a1d5074 P 28b0ac15567342229edb62e5d18b07d7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.437896 28317 tablet_server.cc:196] TabletServer@127.27.167.65:0 shutdown complete.
I20260812 06:19:03.471735 28317 master.cc:562] Master@127.27.167.126:36553 shutting down...
I20260812 06:19:03.475338 28317 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:03.475566 28317 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:03.475662 28317 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8df569d9a577492dbbc4a17cd00c1403: stopping tablet replica
I20260812 06:19:03.488201 28317 master.cc:584] Master@127.27.167.126:36553 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5525 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10897 ms total)

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