[==========] 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:17:10.282685 22389 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.221.126:37545
I20260812 06:17:10.283726 22389 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:17:10.284332 22389 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:10.291003 22389 server_base.cc:1061] running on GCE node
W20260812 06:17:10.292637 22398 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:17:10.292838 22394 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:17:10.293246 22395 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:17:10.293840 22389 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.293938 22389 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:17:10.294006 22389 hybrid_clock.cc:648] HybridClock initialized: now 1786515430294004 us; error 0 us; skew 500 ppm
I20260812 06:17:10.295943 22389 webserver.cc:533] Webserver started at http://127.21.221.126:40337/ using document root <none> and password file <none>
I20260812 06:17:10.296502 22389 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.296568 22389 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.296782 22389 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.298588 22389 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/master-0-root/instance:
uuid: "b3d98f32d467447bad86c8a3fd9fc05e"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-njxd"
I20260812 06:17:10.302323 22389 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:10.304921 22404 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:17:10.306094 22389 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:10.306244 22389 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/master-0-root
uuid: "b3d98f32d467447bad86c8a3fd9fc05e"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-njxd"
I20260812 06:17:10.306363 22389 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-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:17:10.320111 22389 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.320814 22389 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:17:10.321005 22389 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.329353 22389 rpc_server.cc:307] RPC server started. Bound to: 127.21.221.126:37545
I20260812 06:17:10.329360 22461 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.221.126:37545 every 8 connection(s)
I20260812 06:17:10.331712 22462 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:17:10.337363 22462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: Bootstrap starting.
I20260812 06:17:10.339773 22462 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.340725 22462 log.cc:826] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:10.342697 22462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: No bootstrap required, opened a new log
I20260812 06:17:10.345837 22462 raft_consensus.cc:359] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER }
I20260812 06:17:10.346035 22462 raft_consensus.cc:385] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.346134 22462 raft_consensus.cc:740] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b3d98f32d467447bad86c8a3fd9fc05e, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.346813 22462 consensus_queue.cc:260] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [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: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER }
I20260812 06:17:10.346990 22462 raft_consensus.cc:399] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.347067 22462 raft_consensus.cc:493] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.347258 22462 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.348258 22462 raft_consensus.cc:515] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER }
I20260812 06:17:10.348769 22462 leader_election.cc:304] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [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: b3d98f32d467447bad86c8a3fd9fc05e; no voters: 
I20260812 06:17:10.349133 22462 leader_election.cc:290] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.349308 22465 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.349637 22465 raft_consensus.cc:697] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 1 LEADER]: Becoming Leader. State: Replica: b3d98f32d467447bad86c8a3fd9fc05e, State: Running, Role: LEADER
I20260812 06:17:10.350097 22465 consensus_queue.cc:237] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [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: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER }
I20260812 06:17:10.350322 22462 sys_catalog.cc:565] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:10.352126 22467 sys_catalog.cc:455] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER } }
I20260812 06:17:10.352197 22468 sys_catalog.cc:455] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [sys.catalog]: SysCatalogTable state changed. Reason: New leader b3d98f32d467447bad86c8a3fd9fc05e. Latest consensus state: current_term: 1 leader_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b3d98f32d467447bad86c8a3fd9fc05e" member_type: VOTER } }
I20260812 06:17:10.352267 22467 sys_catalog.cc:458] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.352306 22468 sys_catalog.cc:458] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.352772 22389 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:10.352730 22482 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:10.355531 22482 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:10.360737 22482 catalog_manager.cc:1383] Generated new cluster ID: 31dc0e97bbe642dbb1b9c6c63f3e5e6d
I20260812 06:17:10.360827 22482 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:10.370905 22482 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:10.371815 22482 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:10.376868 22482 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: Generated new TSK 0
I20260812 06:17:10.377514 22482 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:10.385535 22389 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.388748 22489 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:17:10.388849 22493 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:17:10.388744 22491 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:17:10.389086 22389 server_base.cc:1061] running on GCE node
I20260812 06:17:10.389282 22389 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.389338 22389 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:17:10.389372 22389 hybrid_clock.cc:648] HybridClock initialized: now 1786515430389371 us; error 0 us; skew 500 ppm
I20260812 06:17:10.390386 22389 webserver.cc:533] Webserver started at http://127.21.221.65:37329/ using document root <none> and password file <none>
I20260812 06:17:10.390587 22389 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.390688 22389 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.390775 22389 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.391201 22389 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/instance:
uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-njxd"
I20260812 06:17:10.392876 22389 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:10.393950 22499 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:17:10.394212 22389 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.394286 22389 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root
uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-njxd"
I20260812 06:17:10.394381 22389 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-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:17:10.406057 22389 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.406548 22389 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.407091 22389 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:10.407963 22389 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:10.408015 22389 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.408078 22389 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:10.408118 22389 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.415066 22389 rpc_server.cc:307] RPC server started. Bound to: 127.21.221.65:46555
I20260812 06:17:10.415094 22567 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.221.65:46555 every 8 connection(s)
I20260812 06:17:10.429666 22568 heartbeater.cc:344] Connected to a master server at 127.21.221.126:37545
I20260812 06:17:10.429946 22568 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:10.430440 22568 heartbeater.cc:507] Master 127.21.221.126:37545 requested a full tablet report, sending...
I20260812 06:17:10.432035 22424 ts_manager.cc:194] Registered new tserver with Master: 848dfdd0bc3e4dec9c3d9a007c5530fe (127.21.221.65:46555)
I20260812 06:17:10.432355 22389 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016621583s
I20260812 06:17:10.433708 22424 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57788
I20260812 06:17:10.442780 22424 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57804:
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:17:10.458367 22530 tablet_service.cc:1511] Processing CreateTablet for tablet d06069c02b2e48ecb4e44198e2a2b7de (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1cdfb5ee5c4413c9be277228179a64a]), partition=
I20260812 06:17:10.458897 22530 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d06069c02b2e48ecb4e44198e2a2b7de. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.461174 22582 tablet_bootstrap.cc:492] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Bootstrap starting.
I20260812 06:17:10.462435 22582 tablet_bootstrap.cc:654] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.463641 22582 tablet_bootstrap.cc:492] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: No bootstrap required, opened a new log
I20260812 06:17:10.463775 22582 ts_tablet_manager.cc:1403] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:10.464228 22582 raft_consensus.cc:359] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 46555 } }
I20260812 06:17:10.464352 22582 raft_consensus.cc:385] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.464402 22582 raft_consensus.cc:740] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 848dfdd0bc3e4dec9c3d9a007c5530fe, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.464561 22582 consensus_queue.cc:260] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [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: "848dfdd0bc3e4dec9c3d9a007c5530fe" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 46555 } }
I20260812 06:17:10.464681 22582 raft_consensus.cc:399] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.464761 22582 raft_consensus.cc:493] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.464819 22582 raft_consensus.cc:3060] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.465682 22582 raft_consensus.cc:515] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 46555 } }
I20260812 06:17:10.465857 22582 leader_election.cc:304] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [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: 848dfdd0bc3e4dec9c3d9a007c5530fe; no voters: 
I20260812 06:17:10.466109 22582 leader_election.cc:290] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.466511 22584 raft_consensus.cc:2804] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.466547 22582 ts_tablet_manager.cc:1434] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:10.466924 22584 raft_consensus.cc:697] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 1 LEADER]: Becoming Leader. State: Replica: 848dfdd0bc3e4dec9c3d9a007c5530fe, State: Running, Role: LEADER
I20260812 06:17:10.467000 22568 heartbeater.cc:499] Master 127.21.221.126:37545 was elected leader, sending a full tablet report...
I20260812 06:17:10.467115 22584 consensus_queue.cc:237] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [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: "848dfdd0bc3e4dec9c3d9a007c5530fe" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 46555 } }
I20260812 06:17:10.469962 22424 catalog_manager.cc:5719] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe reported cstate change: term changed from 0 to 1, leader changed from <none> to 848dfdd0bc3e4dec9c3d9a007c5530fe (127.21.221.65). New cstate: current_term: 1 leader_uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848dfdd0bc3e4dec9c3d9a007c5530fe" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 46555 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:10.546221 22389 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.026s	sys 0.008s
I20260812 06:17:10.666196 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=15.086190
I20260812 06:17:10.805967 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.139s	user 0.119s	sys 0.020s Metrics: {"bytes_written":8697369,"cfile_init":1,"compiler_manager_pool.queue_time_us":267,"delete_count":0,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":929,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33575,"lbm_writes_lt_1ms":569,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":267136,"thread_start_us":133,"threads_started":1,"update_count":1060}
I20260812 06:17:10.807250 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de): free 11976772 bytes of WAL
I20260812 06:17:10.807580 22504 log_reader.cc:385] T d06069c02b2e48ecb4e44198e2a2b7de: removed 1 log segments from log reader
I20260812 06:17:10.807683 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000001 (ops 1-6)
I20260812 06:17:10.810293 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:10.810814 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de): 12308960 bytes on disk
I20260812 06:17:10.811498 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.812078 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:10.841892 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.028s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:10.842401 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:10.858882 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.859500 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:10.994704 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.135s	user 0.122s	sys 0.013s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631418,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":605,"lbm_read_time_us":9052,"lbm_reads_lt_1ms":469,"lbm_write_time_us":24547,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":365,"threads_started":5,"update_count":2000}
I20260812 06:17:10.995357 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:11.042081 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.047s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20589,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.042583 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:11.053570 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.054339 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:11.179728 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.125s	user 0.096s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":972,"lbm_read_time_us":10429,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23594,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:17:11.180326 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:11.229066 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.049s	user 0.023s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17335,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.229779 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:11.244901 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.245414 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:11.396689 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.151s	user 0.107s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":8727,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28218,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2000}
I20260812 06:17:11.397405 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:11.442898 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.045s	user 0.009s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.443401 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:11.455542 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.456274 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:11.585482 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":8249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25267,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:11.586117 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:11.630822 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.045s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19179,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.631451 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:11.647971 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.648672 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:11.778258 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.129s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":395,"lbm_read_time_us":9407,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26292,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:11.778880 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:11.833387 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.054s	user 0.020s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22198,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.834079 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:11.844905 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.845706 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.006579 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.161s	user 0.112s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":11283,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26438,"lbm_writes_lt_1ms":443,"mutex_wait_us":100,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:12.007305 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:12.047322 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17555,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.047828 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:12.060253 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4667,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.060804 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.091912 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1541,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:12.092733 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de): free 121006423 bytes of WAL
I20260812 06:17:12.092993 22504 log_reader.cc:385] T d06069c02b2e48ecb4e44198e2a2b7de: removed 12 log segments from log reader
I20260812 06:17:12.093042 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000002 (ops 7-11)
I20260812 06:17:12.093091 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000003 (ops 12-16)
I20260812 06:17:12.093139 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000004 (ops 17-21)
I20260812 06:17:12.093182 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000005 (ops 22-26)
I20260812 06:17:12.093221 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000006 (ops 27-31)
I20260812 06:17:12.093281 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000007 (ops 32-36)
I20260812 06:17:12.093317 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000008 (ops 37-41)
I20260812 06:17:12.093356 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000009 (ops 42-46)
I20260812 06:17:12.093396 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000010 (ops 47-51)
I20260812 06:17:12.093436 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000011 (ops 52-56)
I20260812 06:17:12.093477 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000012 (ops 57-60)
I20260812 06:17:12.093516 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000013 (ops 61-65)
I20260812 06:17:12.121341 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:12.121824 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de): 447 bytes on disk
I20260812 06:17:12.122352 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.122823 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=4.173312
I20260812 06:17:12.150465 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.027s	user 0.008s	sys 0.019s Metrics: {"bytes_written":6071825,"delete_count":0,"lbm_write_time_us":7491,"lbm_writes_lt_1ms":151,"reinsert_count":0,"update_count":740}
I20260812 06:17:12.150971 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.161686 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2133453,"delete_count":0,"lbm_write_time_us":3305,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:17:12.162197 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.369280 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.207s	user 0.130s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":330,"lbm_read_time_us":14756,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35046,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:12.370018 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:12.435779 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.066s	user 0.031s	sys 0.032s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24700,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.436468 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:12.453389 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.017s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.454032 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.631803 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.178s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":13268,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29429,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.632405 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=11.118625
I20260812 06:17:12.682111 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":21162,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.682543 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:12.694298 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.694744 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:12.718916 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.024s	user 0.008s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5266,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.719521 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:12.903146 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.183s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1013,"lbm_read_time_us":15055,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30007,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:17:12.903977 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:12.936362 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13956,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.936918 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:12.949841 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.013s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.950531 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:13.083977 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.133s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":934,"lbm_read_time_us":9103,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25470,"lbm_writes_lt_1ms":443,"mutex_wait_us":301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:17:13.084637 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:13.129858 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.045s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14723,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.130390 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:13.141577 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.142218 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:13.267122 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.125s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":8331,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24093,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.267737 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:13.308017 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.040s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307496,"delete_count":0,"lbm_write_time_us":16835,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.308635 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:13.324602 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.325289 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:13.456781 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.131s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631318,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":782,"lbm_read_time_us":9180,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25287,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.457785 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=10.126437
I20260812 06:17:13.510532 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.053s	user 0.039s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17072,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.511207 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:13.522104 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.522658 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:13.561439 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.039s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1449,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:13.562212 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de): free 111786272 bytes of WAL
I20260812 06:17:13.562441 22504 log_reader.cc:385] T d06069c02b2e48ecb4e44198e2a2b7de: removed 11 log segments from log reader
I20260812 06:17:13.562486 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000014 (ops 66-70)
I20260812 06:17:13.562515 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000015 (ops 71-75)
I20260812 06:17:13.562579 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000016 (ops 76-80)
I20260812 06:17:13.562621 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000017 (ops 81-84)
I20260812 06:17:13.562664 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000018 (ops 85-89)
I20260812 06:17:13.562737 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000019 (ops 90-94)
I20260812 06:17:13.562778 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000020 (ops 95-98)
I20260812 06:17:13.562820 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000021 (ops 99-103)
I20260812 06:17:13.562860 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000022 (ops 104-108)
I20260812 06:17:13.562911 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000023 (ops 109-113)
I20260812 06:17:13.562951 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000024 (ops 114-118)
I20260812 06:17:13.586927 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.025s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:17:13.587384 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=3.181125
I20260812 06:17:13.610729 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.023s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.611230 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:13.621241 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.621765 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de): 447 bytes on disk
I20260812 06:17:13.622195 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.622689 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:13.875478 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.253s	user 0.163s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5433,"dirs.run_cpu_time_us":717,"dirs.run_wall_time_us":3318,"lbm_read_time_us":13678,"lbm_reads_lt_1ms":674,"lbm_write_time_us":46411,"lbm_writes_lt_1ms":643,"mutex_wait_us":3756,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:13.876153 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:13.946694 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.065s	user 0.044s	sys 0.020s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":28450,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.947379 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:13.965027 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.965550 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:14.181996 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.216s	user 0.167s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733730,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1149,"lbm_read_time_us":16959,"lbm_reads_lt_1ms":572,"lbm_write_time_us":38757,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:14.182612 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:14.238722 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.056s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20824,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.239329 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:14.257834 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.018s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.258615 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:14.456550 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.198s	user 0.139s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":18141,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":32276,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:17:14.457127 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:14.522668 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.065s	user 0.036s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22957,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.523243 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:14.534264 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.534799 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:14.723132 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.188s	user 0.142s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":12685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32447,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:14.723744 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:14.775022 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.051s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19761,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.775491 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:14.796612 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.021s	user 0.003s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.797390 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:14.996436 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.199s	user 0.112s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1079,"lbm_read_time_us":11934,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32459,"lbm_writes_lt_1ms":543,"mutex_wait_us":481,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:14.997210 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:15.046893 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.049s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21655,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.047478 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:15.064581 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.065701 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:15.257930 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.192s	user 0.137s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":11265,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28453,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:15.258873 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=14.095187
I20260812 06:17:15.306325 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.047s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.306924 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:15.319202 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.320390 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:15.358899 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushMRSOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.038s	user 0.029s	sys 0.008s Metrics: {"bytes_written":1316416,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2034,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:15.359709 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de): free 133477658 bytes of WAL
I20260812 06:17:15.359966 22504 log_reader.cc:385] T d06069c02b2e48ecb4e44198e2a2b7de: removed 13 log segments from log reader
I20260812 06:17:15.360014 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000025 (ops 119-123)
I20260812 06:17:15.360045 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000026 (ops 124-128)
I20260812 06:17:15.360085 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000027 (ops 129-133)
I20260812 06:17:15.360140 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000028 (ops 134-138)
I20260812 06:17:15.360198 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000029 (ops 139-143)
I20260812 06:17:15.360286 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000030 (ops 144-148)
I20260812 06:17:15.360327 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000031 (ops 149-153)
I20260812 06:17:15.360405 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000032 (ops 154-158)
I20260812 06:17:15.360479 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000033 (ops 159-163)
I20260812 06:17:15.360551 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000034 (ops 164-168)
I20260812 06:17:15.360617 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000035 (ops 169-173)
I20260812 06:17:15.360689 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000036 (ops 174-178)
I20260812 06:17:15.360747 22504 log.cc:1079] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/d06069c02b2e48ecb4e44198e2a2b7de/wal-000000037 (ops 179-183)
I20260812 06:17:15.394973 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: LogGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:17:15.395984 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de): 493 bytes on disk
I20260812 06:17:15.396674 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: UndoDeltaBlockGCOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.397456 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=5.165500
I20260812 06:17:15.415156 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":7076,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:17:15.415913 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:15.422776 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.007s	user 0.005s	sys 0.001s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1897,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:17:15.423353 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:15.664318 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.241s	user 0.151s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938719,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":629,"lbm_read_time_us":15399,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38225,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16768,"thread_start_us":98,"threads_started":1,"update_count":3500}
I20260812 06:17:15.665221 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=18.063937
I20260812 06:17:15.732724 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.067s	user 0.029s	sys 0.028s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":27292,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:15.733278 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=2.188937
I20260812 06:17:15.744529 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: FlushDeltaMemStoresOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.745097 22569 maintenance_manager.cc:419] P 848dfdd0bc3e4dec9c3d9a007c5530fe: Scheduling MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de): perf score=1.000000
I20260812 06:17:15.785462 22389 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.239s	user 1.801s	sys 0.219s
I20260812 06:17:15.867892 22389 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.002s	sys 0.000s
I20260812 06:17:15.868625 22389 tablet_server.cc:179] TabletServer@127.21.221.65:0 shutting down...
I20260812 06:17:15.929426 22504 maintenance_manager.cc:643] P 848dfdd0bc3e4dec9c3d9a007c5530fe: MajorDeltaCompactionOp(d06069c02b2e48ecb4e44198e2a2b7de) complete. Timing: real 0.184s	user 0.132s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836136,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":15936,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29945,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":3000}
I20260812 06:17:15.930260 22389 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:15.930737 22389 tablet_replica.cc:333] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe: stopping tablet replica
I20260812 06:17:15.931012 22389 raft_consensus.cc:2243] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.931277 22389 raft_consensus.cc:2272] T d06069c02b2e48ecb4e44198e2a2b7de P 848dfdd0bc3e4dec9c3d9a007c5530fe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.948807 22389 tablet_server.cc:196] TabletServer@127.21.221.65:0 shutdown complete.
I20260812 06:17:15.983261 22389 master.cc:562] Master@127.21.221.126:37545 shutting down...
I20260812 06:17:15.986598 22389 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.986830 22389 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.986917 22389 tablet_replica.cc:333] T 00000000000000000000000000000000 P b3d98f32d467447bad86c8a3fd9fc05e: stopping tablet replica
I20260812 06:17:15.999374 22389 master.cc:584] Master@127.21.221.126:37545 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5815 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:16.108611 22389 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.221.126:39841
I20260812 06:17:16.109192 22389 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.111393 22603 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:17:16.111419 22606 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:17:16.111393 22604 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:17:16.111583 22389 server_base.cc:1061] running on GCE node
I20260812 06:17:16.111789 22389 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.111852 22389 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:17:16.111877 22389 hybrid_clock.cc:648] HybridClock initialized: now 1786515436111876 us; error 0 us; skew 500 ppm
I20260812 06:17:16.112743 22389 webserver.cc:533] Webserver started at http://127.21.221.126:32827/ using document root <none> and password file <none>
I20260812 06:17:16.112927 22389 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.112998 22389 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.113080 22389 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.113497 22389 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/master-0-root/instance:
uuid: "9677bbb0e1df440f921b98b3430a6e00"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-njxd"
I20260812 06:17:16.115207 22389 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:16.116185 22611 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:17:16.116430 22389 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:16.116523 22389 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/master-0-root
uuid: "9677bbb0e1df440f921b98b3430a6e00"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-njxd"
I20260812 06:17:16.116613 22389 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-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:17:16.159057 22389 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.159534 22389 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.164263 22389 rpc_server.cc:307] RPC server started. Bound to: 127.21.221.126:39841
I20260812 06:17:16.170737 22670 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:17:16.171818 22669 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.221.126:39841 every 8 connection(s)
I20260812 06:17:16.172995 22670 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00: Bootstrap starting.
I20260812 06:17:16.173890 22670 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.174989 22670 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00: No bootstrap required, opened a new log
I20260812 06:17:16.175417 22670 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER }
I20260812 06:17:16.175527 22670 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.175577 22670 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9677bbb0e1df440f921b98b3430a6e00, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.175762 22670 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [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: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER }
I20260812 06:17:16.175872 22670 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.175920 22670 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.175984 22670 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.176725 22670 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER }
I20260812 06:17:16.176879 22670 leader_election.cc:304] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [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: 9677bbb0e1df440f921b98b3430a6e00; no voters: 
I20260812 06:17:16.177093 22670 leader_election.cc:290] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.177362 22674 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.177603 22674 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 1 LEADER]: Becoming Leader. State: Replica: 9677bbb0e1df440f921b98b3430a6e00, State: Running, Role: LEADER
I20260812 06:17:16.177654 22670 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:16.177781 22674 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [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: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER }
I20260812 06:17:16.178249 22677 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9677bbb0e1df440f921b98b3430a6e00. Latest consensus state: current_term: 1 leader_uuid: "9677bbb0e1df440f921b98b3430a6e00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER } }
I20260812 06:17:16.178229 22675 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9677bbb0e1df440f921b98b3430a6e00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9677bbb0e1df440f921b98b3430a6e00" member_type: VOTER } }
I20260812 06:17:16.178375 22677 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.178442 22675 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:16.179123 22682 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:16.179841 22682 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:16.180087 22389 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:16.181823 22682 catalog_manager.cc:1383] Generated new cluster ID: c06533057041469a8c2463b8b9d71580
I20260812 06:17:16.181886 22682 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:16.187983 22682 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:16.188614 22682 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:16.196610 22682 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00: Generated new TSK 0
I20260812 06:17:16.196853 22682 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:16.212693 22389 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:16.215027 22696 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:17:16.215143 22695 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:17:16.215158 22389 server_base.cc:1061] running on GCE node
W20260812 06:17:16.215342 22698 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:17:16.215651 22389 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:16.215713 22389 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:17:16.215746 22389 hybrid_clock.cc:648] HybridClock initialized: now 1786515436215745 us; error 0 us; skew 500 ppm
I20260812 06:17:16.216676 22389 webserver.cc:533] Webserver started at http://127.21.221.65:41507/ using document root <none> and password file <none>
I20260812 06:17:16.216869 22389 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:16.216943 22389 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:16.217028 22389 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:16.217461 22389 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/instance:
uuid: "dcece511d5c74558a7b3d508774f3112"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-njxd"
I20260812 06:17:16.219121 22389 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:16.220201 22704 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:17:16.220466 22389 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:16.220557 22389 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root
uuid: "dcece511d5c74558a7b3d508774f3112"
format_stamp: "Formatted at 2026-08-12 06:17:16 on dist-test-slave-njxd"
I20260812 06:17:16.220649 22389 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-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:17:16.226971 22389 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.227388 22389 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.227713 22389 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:16.228206 22389 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:16.228264 22389 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.228325 22389 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:16.228371 22389 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.233067 22389 rpc_server.cc:307] RPC server started. Bound to: 127.21.221.65:34157
I20260812 06:17:16.233098 22776 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.221.65:34157 every 8 connection(s)
I20260812 06:17:16.243618 22777 heartbeater.cc:344] Connected to a master server at 127.21.221.126:39841
I20260812 06:17:16.243781 22777 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:16.244057 22777 heartbeater.cc:507] Master 127.21.221.126:39841 requested a full tablet report, sending...
I20260812 06:17:16.244801 22630 ts_manager.cc:194] Registered new tserver with Master: dcece511d5c74558a7b3d508774f3112 (127.21.221.65:34157)
I20260812 06:17:16.245617 22630 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57066
I20260812 06:17:16.245764 22389 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0122404s
I20260812 06:17:16.253063 22630 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57072:
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:17:16.262290 22736 tablet_service.cc:1511] Processing CreateTablet for tablet 919a77d3aaf7451b93e6bbeaddfaf36c (DEFAULT_TABLE table=heavy-update-compaction-test [id=f7c9954b788c4ef1a4d85d8247d02b8e]), partition=
I20260812 06:17:16.262624 22736 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 919a77d3aaf7451b93e6bbeaddfaf36c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:16.264804 22790 tablet_bootstrap.cc:492] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Bootstrap starting.
I20260812 06:17:16.265761 22790 tablet_bootstrap.cc:654] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.266948 22790 tablet_bootstrap.cc:492] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: No bootstrap required, opened a new log
I20260812 06:17:16.267032 22790 ts_tablet_manager.cc:1403] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:16.267534 22790 raft_consensus.cc:359] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dcece511d5c74558a7b3d508774f3112" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 34157 } }
I20260812 06:17:16.267673 22790 raft_consensus.cc:385] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.267710 22790 raft_consensus.cc:740] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dcece511d5c74558a7b3d508774f3112, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.267846 22790 consensus_queue.cc:260] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [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: "dcece511d5c74558a7b3d508774f3112" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 34157 } }
I20260812 06:17:16.267961 22790 raft_consensus.cc:399] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.268014 22790 raft_consensus.cc:493] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.268070 22790 raft_consensus.cc:3060] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.268836 22790 raft_consensus.cc:515] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dcece511d5c74558a7b3d508774f3112" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 34157 } }
I20260812 06:17:16.268963 22790 leader_election.cc:304] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [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: dcece511d5c74558a7b3d508774f3112; no voters: 
I20260812 06:17:16.269150 22790 leader_election.cc:290] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.269328 22792 raft_consensus.cc:2804] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.269507 22777 heartbeater.cc:499] Master 127.21.221.126:39841 was elected leader, sending a full tablet report...
I20260812 06:17:16.269546 22792 raft_consensus.cc:697] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 1 LEADER]: Becoming Leader. State: Replica: dcece511d5c74558a7b3d508774f3112, State: Running, Role: LEADER
I20260812 06:17:16.269515 22790 ts_tablet_manager.cc:1434] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:16.269696 22792 consensus_queue.cc:237] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [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: "dcece511d5c74558a7b3d508774f3112" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 34157 } }
I20260812 06:17:16.271065 22630 catalog_manager.cc:5719] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 reported cstate change: term changed from 0 to 1, leader changed from <none> to dcece511d5c74558a7b3d508774f3112 (127.21.221.65). New cstate: current_term: 1 leader_uuid: "dcece511d5c74558a7b3d508774f3112" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dcece511d5c74558a7b3d508774f3112" member_type: VOTER last_known_addr { host: "127.21.221.65" port: 34157 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:16.331810 22389 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:17:16.484015 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=19.054940
I20260812 06:17:16.650537 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.166s	user 0.142s	sys 0.024s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":814,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41452,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:16.651409 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): free 20743880 bytes of WAL
I20260812 06:17:16.651708 22709 log_reader.cc:385] T 919a77d3aaf7451b93e6bbeaddfaf36c: removed 2 log segments from log reader
I20260812 06:17:16.651777 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000001 (ops 1-6)
I20260812 06:17:16.651821 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000002 (ops 7-11)
I20260812 06:17:16.657927 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:16.658614 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): 16411395 bytes on disk
I20260812 06:17:16.659130 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.659591 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:16.673358 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.674072 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:16.830456 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.156s	user 0.107s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":10802,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28525,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":337,"threads_started":5,"update_count":2000}
I20260812 06:17:16.831116 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:16.879448 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.048s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:17:16.880137 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:16.900219 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.900688 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.055701 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.155s	user 0.115s	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":316,"lbm_read_time_us":10824,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25638,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2000}
I20260812 06:17:17.056372 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:17.093938 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.037s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.094659 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:17.109402 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.110143 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.241421 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.131s	user 0.097s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":952,"lbm_read_time_us":7804,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25448,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:17:17.242282 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:17.300274 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.058s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":36366,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.300820 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:17.312659 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.313406 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.452416 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.139s	user 0.102s	sys 0.036s 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":999,"lbm_read_time_us":10725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25628,"lbm_writes_lt_1ms":443,"mutex_wait_us":344,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44928,"update_count":2000}
I20260812 06:17:17.452986 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:17.503038 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.050s	user 0.020s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15814,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.503677 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:17.520776 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.017s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.521489 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.672495 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.151s	user 0.098s	sys 0.053s 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":354,"lbm_read_time_us":11463,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23296,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:17:17.673101 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:17.729401 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.056s	user 0.016s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.730031 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:17.743125 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.743585 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.875661 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.132s	user 0.111s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":9879,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26074,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31616,"update_count":2000}
I20260812 06:17:17.876443 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:17.920873 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.044s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16147,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.921396 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:17.933308 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.933985 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:17.964438 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1231,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:17.965163 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): free 111786258 bytes of WAL
I20260812 06:17:17.965442 22709 log_reader.cc:385] T 919a77d3aaf7451b93e6bbeaddfaf36c: removed 11 log segments from log reader
I20260812 06:17:17.965507 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000003 (ops 12-16)
I20260812 06:17:17.965545 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000004 (ops 17-21)
I20260812 06:17:17.965605 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000005 (ops 22-26)
I20260812 06:17:17.965646 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000006 (ops 27-31)
I20260812 06:17:17.965678 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000007 (ops 32-36)
I20260812 06:17:17.965708 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000008 (ops 37-40)
I20260812 06:17:17.965739 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000009 (ops 41-45)
I20260812 06:17:17.965768 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000010 (ops 46-50)
I20260812 06:17:17.965802 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000011 (ops 51-55)
I20260812 06:17:17.965835 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000012 (ops 56-60)
I20260812 06:17:17.965864 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000013 (ops 61-64)
I20260812 06:17:17.995630 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:17.996094 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): 447 bytes on disk
I20260812 06:17:17.996589 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.997310 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.021481 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.022042 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.033080 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.033726 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:18.209794 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.176s	user 0.135s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877342,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":604,"lbm_read_time_us":12940,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34910,"lbm_writes_lt_1ms":643,"mutex_wait_us":81,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28928,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:18.210547 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:18.258940 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.048s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20309,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.259650 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.272639 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.273301 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:18.446226 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.173s	user 0.105s	sys 0.054s 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":463,"lbm_read_time_us":9468,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33151,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:17:18.446997 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:18.500069 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.053s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24067,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.500816 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:18.653544 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.152s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":145,"lbm_read_time_us":9670,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27626,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:17:18.654461 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:18.688647 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.034s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14937,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.689306 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.706902 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.707427 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:18.842059 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.134s	user 0.107s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1573,"lbm_read_time_us":10274,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26573,"lbm_writes_lt_1ms":443,"mutex_wait_us":435,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:17:18.842787 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=10.126437
I20260812 06:17:18.889655 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.047s	user 0.034s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20993,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.890292 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.920463 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.030s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6586,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":500}
I20260812 06:17:18.921003 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:18.931769 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.932276 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:19.103137 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.171s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":912,"lbm_read_time_us":10292,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31027,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":201728,"update_count":2500}
I20260812 06:17:19.103945 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:19.157640 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.053s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21643,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.158169 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:19.170271 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.170742 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:19.326856 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.156s	user 0.106s	sys 0.036s 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":257,"lbm_read_time_us":9187,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29801,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:19.327644 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:19.382054 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.054s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24438,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.382668 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:19.438110 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.055s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1305,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1816,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:19.438818 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): free 121459489 bytes of WAL
I20260812 06:17:19.439064 22709 log_reader.cc:385] T 919a77d3aaf7451b93e6bbeaddfaf36c: removed 12 log segments from log reader
I20260812 06:17:19.439108 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000014 (ops 65-69)
I20260812 06:17:19.439138 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000015 (ops 70-74)
I20260812 06:17:19.439204 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000016 (ops 75-79)
I20260812 06:17:19.439247 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000017 (ops 80-84)
I20260812 06:17:19.439296 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000018 (ops 85-89)
I20260812 06:17:19.439337 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000019 (ops 90-94)
I20260812 06:17:19.439365 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000020 (ops 95-99)
I20260812 06:17:19.439404 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000021 (ops 100-104)
I20260812 06:17:19.439445 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000022 (ops 105-109)
I20260812 06:17:19.439484 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000023 (ops 110-114)
I20260812 06:17:19.439528 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000024 (ops 115-119)
I20260812 06:17:19.439570 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000025 (ops 120-124)
I20260812 06:17:19.467665 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.029s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:17:19.468351 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): 472 bytes on disk
I20260812 06:17:19.468825 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.469445 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=7.149875
I20260812 06:17:19.490100 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.020s	user 0.016s	sys 0.003s Metrics: {"bytes_written":8697369,"delete_count":0,"lbm_write_time_us":8583,"lbm_writes_lt_1ms":215,"reinsert_count":0,"update_count":1060}
I20260812 06:17:19.490625 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:19.509228 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5857,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:17:19.509773 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:19.735224 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.225s	user 0.154s	sys 0.071s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979618,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":299,"lbm_read_time_us":15050,"lbm_reads_lt_1ms":765,"lbm_write_time_us":43263,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:19.736014 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=18.063937
I20260812 06:17:19.801784 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.066s	user 0.035s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29248,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.802312 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:19.814635 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.815322 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:19.983812 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.168s	user 0.127s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":11557,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34342,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:19.985093 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:20.035452 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.050s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16615023,"delete_count":0,"lbm_write_time_us":21451,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2025}
I20260812 06:17:20.036048 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.061434 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.025s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5389,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:20.061966 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.072820 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.073338 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:20.244200 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.171s	user 0.130s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":569,"lbm_read_time_us":11891,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36319,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":3000}
I20260812 06:17:20.244922 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:20.302201 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.057s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24801,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.302704 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.314850 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.315333 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:20.479986 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.164s	user 0.116s	sys 0.045s 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":214,"lbm_read_time_us":11304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33022,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:20.480608 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=12.110812
I20260812 06:17:20.522982 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.042s	user 0.017s	sys 0.023s Metrics: {"bytes_written":13620266,"delete_count":0,"lbm_write_time_us":19100,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:17:20.523792 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.196750
I20260812 06:17:20.534179 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3351,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:20.534816 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:20.696225 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.161s	user 0.105s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1008,"lbm_read_time_us":9469,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27589,"lbm_writes_lt_1ms":443,"mutex_wait_us":356,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:17:20.696965 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=14.095187
I20260812 06:17:20.746306 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.049s	user 0.013s	sys 0.035s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23541,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.746940 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.768672 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.022s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.769244 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:20.800583 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushMRSOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1384,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1469,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:20.801503 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): free 120553642 bytes of WAL
I20260812 06:17:20.801815 22709 log_reader.cc:385] T 919a77d3aaf7451b93e6bbeaddfaf36c: removed 12 log segments from log reader
I20260812 06:17:20.801885 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000026 (ops 125-129)
I20260812 06:17:20.801940 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000027 (ops 130-134)
I20260812 06:17:20.802003 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000028 (ops 135-138)
I20260812 06:17:20.802045 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000029 (ops 139-143)
I20260812 06:17:20.802085 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000030 (ops 144-148)
I20260812 06:17:20.802136 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000031 (ops 149-153)
I20260812 06:17:20.802174 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000032 (ops 154-158)
I20260812 06:17:20.802212 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000033 (ops 159-162)
I20260812 06:17:20.802250 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000034 (ops 163-167)
I20260812 06:17:20.802286 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000035 (ops 168-172)
I20260812 06:17:20.802323 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000036 (ops 173-177)
I20260812 06:17:20.802361 22709 log.cc:1079] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: Deleting log segment in path: /tmp/dist-test-taskABmMJ9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430271466-22389-0/minicluster-data/ts-0-root/wals/919a77d3aaf7451b93e6bbeaddfaf36c/wal-000000037 (ops 178-182)
I20260812 06:17:20.828753 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: LogGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:20.829273 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c): 447 bytes on disk
I20260812 06:17:20.829994 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: UndoDeltaBlockGCOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.830641 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.848058 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.848546 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=2.188937
I20260812 06:17:20.863775 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.864406 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:21.122202 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.258s	user 0.157s	sys 0.099s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979748,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":448,"lbm_read_time_us":17252,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42407,"lbm_writes_lt_1ms":743,"mutex_wait_us":121,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:17:21.123114 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=16.079562
I20260812 06:17:21.189376 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.066s	user 0.032s	sys 0.020s Metrics: {"bytes_written":18420088,"delete_count":0,"lbm_write_time_us":25265,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":451,"reinsert_count":0,"update_count":2245}
I20260812 06:17:21.189998 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=4.173312
I20260812 06:17:21.207429 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: FlushDeltaMemStoresOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":6194903,"delete_count":0,"lbm_write_time_us":6821,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:17:21.208088 22779 maintenance_manager.cc:419] P dcece511d5c74558a7b3d508774f3112: Scheduling MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c): perf score=1.000000
I20260812 06:17:21.280778 22389 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.949s	user 1.848s	sys 0.143s
I20260812 06:17:21.355571 22389 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.001s	sys 0.000s
I20260812 06:17:21.356138 22389 tablet_server.cc:179] TabletServer@127.21.221.65:0 shutting down...
I20260812 06:17:21.392693 22709 maintenance_manager.cc:643] P dcece511d5c74558a7b3d508774f3112: MajorDeltaCompactionOp(919a77d3aaf7451b93e6bbeaddfaf36c) complete. Timing: real 0.184s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877113,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":973,"lbm_read_time_us":14302,"lbm_reads_lt_1ms":668,"lbm_write_time_us":31611,"lbm_writes_lt_1ms":643,"mutex_wait_us":274,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:21.393532 22389 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:21.393847 22389 tablet_replica.cc:333] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112: stopping tablet replica
I20260812 06:17:21.394001 22389 raft_consensus.cc:2243] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.394208 22389 raft_consensus.cc:2272] T 919a77d3aaf7451b93e6bbeaddfaf36c P dcece511d5c74558a7b3d508774f3112 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.411549 22389 tablet_server.cc:196] TabletServer@127.21.221.65:0 shutdown complete.
I20260812 06:17:21.444422 22389 master.cc:562] Master@127.21.221.126:39841 shutting down...
I20260812 06:17:21.448166 22389 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.448385 22389 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.448485 22389 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9677bbb0e1df440f921b98b3430a6e00: stopping tablet replica
I20260812 06:17:21.460924 22389 master.cc:584] Master@127.21.221.126:39841 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5453 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11270 ms total)

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