[==========] 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:51.424734 15716 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.89.62:36397
I20260812 06:17:51.425750 15716 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:51.426358 15716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:51.433444 15727 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:51.433535 15716 server_base.cc:1061] running on GCE node
W20260812 06:17:51.433485 15732 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:51.433444 15730 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:51.434166 15716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:51.434306 15716 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:51.434371 15716 hybrid_clock.cc:648] HybridClock initialized: now 1786515471434369 us; error 0 us; skew 500 ppm
I20260812 06:17:51.436151 15716 webserver.cc:533] Webserver started at http://127.15.89.62:45363/ using document root <none> and password file <none>
I20260812 06:17:51.436692 15716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:51.436776 15716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:51.437034 15716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:51.438653 15716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/master-0-root/instance:
uuid: "b6c691791c4245a9945808d1065a6689"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-92m1"
I20260812 06:17:51.442121 15716 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:51.444202 15739 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:51.445152 15716 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:51.445283 15716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/master-0-root
uuid: "b6c691791c4245a9945808d1065a6689"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-92m1"
I20260812 06:17:51.445384 15716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-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:51.463544 15716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:51.464195 15716 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:51.464375 15716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:51.471877 15716 rpc_server.cc:307] RPC server started. Bound to: 127.15.89.62:36397
I20260812 06:17:51.471891 15818 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.89.62:36397 every 8 connection(s)
I20260812 06:17:51.474133 15823 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:51.479664 15823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: Bootstrap starting.
I20260812 06:17:51.481947 15823 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:51.482868 15823 log.cc:826] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:51.484607 15823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: No bootstrap required, opened a new log
I20260812 06:17:51.487414 15823 raft_consensus.cc:359] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c691791c4245a9945808d1065a6689" member_type: VOTER }
I20260812 06:17:51.487576 15823 raft_consensus.cc:385] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:51.487675 15823 raft_consensus.cc:740] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b6c691791c4245a9945808d1065a6689, State: Initialized, Role: FOLLOWER
I20260812 06:17:51.488343 15823 consensus_queue.cc:260] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [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: "b6c691791c4245a9945808d1065a6689" member_type: VOTER }
I20260812 06:17:51.488492 15823 raft_consensus.cc:399] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:51.488586 15823 raft_consensus.cc:493] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:51.488729 15823 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:51.489548 15823 raft_consensus.cc:515] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c691791c4245a9945808d1065a6689" member_type: VOTER }
I20260812 06:17:51.489993 15823 leader_election.cc:304] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [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: b6c691791c4245a9945808d1065a6689; no voters: 
I20260812 06:17:51.490329 15823 leader_election.cc:290] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:51.490499 15830 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:51.490761 15830 raft_consensus.cc:697] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 1 LEADER]: Becoming Leader. State: Replica: b6c691791c4245a9945808d1065a6689, State: Running, Role: LEADER
I20260812 06:17:51.491235 15830 consensus_queue.cc:237] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [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: "b6c691791c4245a9945808d1065a6689" member_type: VOTER }
I20260812 06:17:51.491408 15823 sys_catalog.cc:565] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:51.493192 15833 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b6c691791c4245a9945808d1065a6689. Latest consensus state: current_term: 1 leader_uuid: "b6c691791c4245a9945808d1065a6689" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c691791c4245a9945808d1065a6689" member_type: VOTER } }
I20260812 06:17:51.493218 15831 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b6c691791c4245a9945808d1065a6689" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c691791c4245a9945808d1065a6689" member_type: VOTER } }
I20260812 06:17:51.493319 15833 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:51.493319 15831 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:51.493705 15848 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:51.493902 15716 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:51.496481 15848 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:51.501423 15848 catalog_manager.cc:1383] Generated new cluster ID: 1e07bf98e8b842158089b8dccc9c1234
I20260812 06:17:51.501508 15848 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:51.528580 15848 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:51.529516 15848 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:51.549737 15848 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: Generated new TSK 0
I20260812 06:17:51.550601 15848 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:51.558779 15716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:51.561549 15860 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:51.561622 15716 server_base.cc:1061] running on GCE node
W20260812 06:17:51.561581 15865 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:51.561735 15861 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:51.562103 15716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:51.562168 15716 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:51.562194 15716 hybrid_clock.cc:648] HybridClock initialized: now 1786515471562194 us; error 0 us; skew 500 ppm
I20260812 06:17:51.563125 15716 webserver.cc:533] Webserver started at http://127.15.89.1:34805/ using document root <none> and password file <none>
I20260812 06:17:51.563319 15716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:51.563390 15716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:51.563470 15716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:51.563860 15716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/instance:
uuid: "9fb9a1e9fa344951aa299fb273e43230"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-92m1"
I20260812 06:17:51.565407 15716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:51.566360 15872 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:51.566619 15716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:51.566689 15716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root
uuid: "9fb9a1e9fa344951aa299fb273e43230"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-92m1"
I20260812 06:17:51.566774 15716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-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:51.590399 15716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:51.591327 15716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:51.591878 15716 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:51.592869 15716 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:51.592924 15716 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:51.592995 15716 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:51.593041 15716 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:51.600061 15716 rpc_server.cc:307] RPC server started. Bound to: 127.15.89.1:43435
I20260812 06:17:51.600127 15980 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.89.1:43435 every 8 connection(s)
I20260812 06:17:51.609997 15983 heartbeater.cc:344] Connected to a master server at 127.15.89.62:36397
I20260812 06:17:51.610265 15983 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:51.610709 15983 heartbeater.cc:507] Master 127.15.89.62:36397 requested a full tablet report, sending...
I20260812 06:17:51.612239 15768 ts_manager.cc:194] Registered new tserver with Master: 9fb9a1e9fa344951aa299fb273e43230 (127.15.89.1:43435)
I20260812 06:17:51.613056 15716 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012344114s
I20260812 06:17:51.613554 15768 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35524
I20260812 06:17:51.623134 15768 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35538:
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:51.638731 15924 tablet_service.cc:1511] Processing CreateTablet for tablet 4ff2406a29b5426b8d67da758a78c1e6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b8f32da9f487482888e60c7f036251b1]), partition=
I20260812 06:17:51.639302 15924 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4ff2406a29b5426b8d67da758a78c1e6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:51.641498 16003 tablet_bootstrap.cc:492] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Bootstrap starting.
I20260812 06:17:51.642973 16003 tablet_bootstrap.cc:654] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:51.644366 16003 tablet_bootstrap.cc:492] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: No bootstrap required, opened a new log
I20260812 06:17:51.644500 16003 ts_tablet_manager.cc:1403] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:51.644964 16003 raft_consensus.cc:359] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9fb9a1e9fa344951aa299fb273e43230" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 43435 } }
I20260812 06:17:51.645099 16003 raft_consensus.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:51.645149 16003 raft_consensus.cc:740] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9fb9a1e9fa344951aa299fb273e43230, State: Initialized, Role: FOLLOWER
I20260812 06:17:51.645299 16003 consensus_queue.cc:260] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [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: "9fb9a1e9fa344951aa299fb273e43230" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 43435 } }
I20260812 06:17:51.645409 16003 raft_consensus.cc:399] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:51.645459 16003 raft_consensus.cc:493] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:51.645516 16003 raft_consensus.cc:3060] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:51.646500 16003 raft_consensus.cc:515] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9fb9a1e9fa344951aa299fb273e43230" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 43435 } }
I20260812 06:17:51.646653 16003 leader_election.cc:304] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [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: 9fb9a1e9fa344951aa299fb273e43230; no voters: 
I20260812 06:17:51.646874 16003 leader_election.cc:290] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:51.647042 16005 raft_consensus.cc:2804] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:51.647289 16003 ts_tablet_manager.cc:1434] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:51.647377 16005 raft_consensus.cc:697] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 1 LEADER]: Becoming Leader. State: Replica: 9fb9a1e9fa344951aa299fb273e43230, State: Running, Role: LEADER
I20260812 06:17:51.647514 15983 heartbeater.cc:499] Master 127.15.89.62:36397 was elected leader, sending a full tablet report...
I20260812 06:17:51.647594 16005 consensus_queue.cc:237] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [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: "9fb9a1e9fa344951aa299fb273e43230" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 43435 } }
I20260812 06:17:51.650595 15768 catalog_manager.cc:5719] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9fb9a1e9fa344951aa299fb273e43230 (127.15.89.1). New cstate: current_term: 1 leader_uuid: "9fb9a1e9fa344951aa299fb273e43230" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9fb9a1e9fa344951aa299fb273e43230" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 43435 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:51.716101 15716 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.006s
I20260812 06:17:51.851533 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=16.078378
I20260812 06:17:52.059707 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.208s	user 0.150s	sys 0.055s Metrics: {"bytes_written":13497197,"cfile_init":1,"compiler_manager_pool.queue_time_us":457,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":293,"dirs.run_wall_time_us":889,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":51283,"lbm_writes_lt_1ms":786,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":187136,"thread_start_us":128,"threads_started":1,"update_count":1645}
I20260812 06:17:52.060992 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 20743880 bytes of WAL
I20260812 06:17:52.061326 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 2 log segments from log reader
I20260812 06:17:52.061408 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000001 (ops 1-6)
I20260812 06:17:52.061537 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000002 (ops 7-11)
I20260812 06:17:52.068130 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:52.068602 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6): 16411393 bytes on disk
I20260812 06:17:52.069325 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":126,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.069793 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=3.181125
I20260812 06:17:52.095422 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.025s	user 0.018s	sys 0.007s Metrics: {"bytes_written":4964170,"delete_count":0,"lbm_write_time_us":7119,"lbm_writes_lt_1ms":124,"reinsert_count":0,"update_count":605}
I20260812 06:17:52.095983 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:52.102999 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2435,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:17:52.103482 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:52.287070 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.183s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774770,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1072,"lbm_read_time_us":13273,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30426,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":324,"threads_started":5,"update_count":2500}
I20260812 06:17:52.287745 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:52.323982 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15834,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.324502 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:52.341470 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.341907 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:52.465500 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.123s	user 0.094s	sys 0.027s 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":300,"lbm_read_time_us":8585,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23297,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:52.466086 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:52.510680 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.044s	user 0.032s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20626,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.511346 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:52.525578 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.526098 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:52.646389 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.120s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":8109,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23453,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:17:52.647029 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:52.690855 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.044s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18782,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.691543 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:52.705345 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.705881 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:52.825922 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.120s	user 0.096s	sys 0.024s 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":346,"lbm_read_time_us":9139,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22579,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:52.826567 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:52.871999 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.045s	user 0.019s	sys 0.026s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17173,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.872537 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:52.883932 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.884383 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.030241 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.146s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":10341,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:17:53.030875 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:53.071727 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.041s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17761,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.072202 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:53.087426 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.088145 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.206727 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.118s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":9441,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21235,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:53.207425 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=10.126437
I20260812 06:17:53.254853 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.047s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22208,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.255488 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:53.266306 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.266911 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.301294 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":380,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":3258,"drs_written":1,"lbm_read_time_us":174,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2706,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:53.302304 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 112239278 bytes of WAL
I20260812 06:17:53.302563 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 11 log segments from log reader
I20260812 06:17:53.302635 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000003 (ops 12-16)
I20260812 06:17:53.302688 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000004 (ops 17-21)
I20260812 06:17:53.302734 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000005 (ops 22-26)
I20260812 06:17:53.302778 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000006 (ops 27-31)
I20260812 06:17:53.302824 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000007 (ops 32-36)
I20260812 06:17:53.302866 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000008 (ops 37-41)
I20260812 06:17:53.302912 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000009 (ops 42-46)
I20260812 06:17:53.302955 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000010 (ops 47-51)
I20260812 06:17:53.302999 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000011 (ops 52-56)
I20260812 06:17:53.303040 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000012 (ops 57-60)
I20260812 06:17:53.303086 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000013 (ops 61-65)
I20260812 06:17:53.325089 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:53.325588 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6): 462 bytes on disk
I20260812 06:17:53.326102 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:53.326736 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=3.181125
I20260812 06:17:53.339100 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4714,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:53.339594 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 12017983 bytes of WAL
I20260812 06:17:53.339835 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 1 log segments from log reader
I20260812 06:17:53.339895 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000014 (ops 66-70)
I20260812 06:17:53.342707 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:53.343031 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:53.355304 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4756,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.355719 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.532819 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.177s	user 0.142s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":682,"lbm_read_time_us":13570,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34551,"lbm_writes_lt_1ms":643,"mutex_wait_us":54,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:53.533608 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:53.591673 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.057s	user 0.020s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25281,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.592176 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:53.604624 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.605186 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.762998 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.158s	user 0.094s	sys 0.056s 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":1200,"lbm_read_time_us":8920,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30897,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:53.763805 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:53.814239 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.050s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22099,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.814713 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:53.950050 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.135s	user 0.093s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":828,"lbm_read_time_us":9467,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22232,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:17:53.950753 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=11.118625
I20260812 06:17:54.002405 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.051s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19248,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:54.002974 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.015013 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.015578 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.030440 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5694,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.030964 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:54.220422 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.189s	user 0.131s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":250,"lbm_read_time_us":10559,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32754,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2500}
I20260812 06:17:54.221251 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:54.283268 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.062s	user 0.041s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":28352,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.283854 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=3.181125
I20260812 06:17:54.303328 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6117,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.303882 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.325160 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.021s	user 0.012s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.325783 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:54.526520 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.201s	user 0.136s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":213,"lbm_read_time_us":15188,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36149,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3000}
I20260812 06:17:54.529867 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:54.594259 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.064s	user 0.046s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26062,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.594779 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.606582 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.607008 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:54.770946 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.164s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":11068,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26866,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:54.771574 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:54.827963 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.056s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:54.828528 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.840231 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4064,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.840732 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:54.878919 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.038s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1217,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2390,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:54.879716 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 121006436 bytes of WAL
I20260812 06:17:54.879947 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 12 log segments from log reader
I20260812 06:17:54.879992 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000015 (ops 71-75)
I20260812 06:17:54.880020 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000016 (ops 76-80)
I20260812 06:17:54.880089 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000017 (ops 81-84)
I20260812 06:17:54.880131 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000018 (ops 85-89)
I20260812 06:17:54.880170 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000019 (ops 90-94)
I20260812 06:17:54.880226 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000020 (ops 95-99)
I20260812 06:17:54.880272 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000021 (ops 100-104)
I20260812 06:17:54.880311 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000022 (ops 105-109)
I20260812 06:17:54.880348 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000023 (ops 110-114)
I20260812 06:17:54.880388 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000024 (ops 115-119)
I20260812 06:17:54.880432 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000025 (ops 120-124)
I20260812 06:17:54.880470 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000026 (ops 125-129)
I20260812 06:17:54.905670 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:54.906229 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.930097 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.023s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.930699 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 12017954 bytes of WAL
I20260812 06:17:54.930954 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 1 log segments from log reader
I20260812 06:17:54.931031 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000027 (ops 130-134)
I20260812 06:17:54.933353 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:54.933681 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:54.945922 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4161,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.946571 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:55.181762 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.235s	user 0.151s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":135,"lbm_read_time_us":15219,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41634,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:17:55.182404 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:55.238901 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.054s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16532973,"delete_count":0,"lbm_write_time_us":21554,"lbm_writes_lt_1ms":406,"mutex_wait_us":808,"reinsert_count":0,"update_count":2015}
I20260812 06:17:55.239494 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6): 493 bytes on disk
I20260812 06:17:55.239998 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.240510 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=3.181125
I20260812 06:17:55.252358 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4389837,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:55.252861 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:55.262184 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3485,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.262728 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:55.454296 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.191s	user 0.135s	sys 0.056s 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":264,"lbm_read_time_us":14131,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31936,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":3000}
I20260812 06:17:55.455049 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:55.503616 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.048s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20639,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:55.504145 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:55.514631 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.515031 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:55.684708 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.170s	user 0.123s	sys 0.044s 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":1146,"lbm_read_time_us":12270,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29344,"lbm_writes_lt_1ms":543,"mutex_wait_us":706,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:55.685428 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=11.118625
I20260812 06:17:55.754520 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.069s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19566,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:55.755013 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=6.157687
I20260812 06:17:55.778988 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.024s	user 0.007s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9330,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:55.779471 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:55.943490 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.164s	user 0.115s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1125,"lbm_read_time_us":10691,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29282,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:55.944028 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:56.008992 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.065s	user 0.031s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25531,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.009630 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:56.020743 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.021238 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:56.192835 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.171s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":12818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27349,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":98048,"update_count":2500}
I20260812 06:17:56.193421 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=14.095187
I20260812 06:17:56.252605 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.059s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22134,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.253175 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:56.263859 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.264293 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:56.293848 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushMRSOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.029s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1252,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1391,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:56.294709 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling LogGCOp(4ff2406a29b5426b8d67da758a78c1e6): free 108535640 bytes of WAL
I20260812 06:17:56.294970 15878 log_reader.cc:385] T 4ff2406a29b5426b8d67da758a78c1e6: removed 11 log segments from log reader
I20260812 06:17:56.295037 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000028 (ops 135-139)
I20260812 06:17:56.295090 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000029 (ops 140-144)
I20260812 06:17:56.295149 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000030 (ops 145-148)
I20260812 06:17:56.295192 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000031 (ops 149-153)
I20260812 06:17:56.295259 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000032 (ops 154-158)
I20260812 06:17:56.295302 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000033 (ops 159-162)
I20260812 06:17:56.295365 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000034 (ops 163-167)
I20260812 06:17:56.295428 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000035 (ops 168-172)
I20260812 06:17:56.295477 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000036 (ops 173-177)
I20260812 06:17:56.295506 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000037 (ops 178-182)
I20260812 06:17:56.295531 15878 log.cc:1079] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/4ff2406a29b5426b8d67da758a78c1e6/wal-000000038 (ops 183-187)
I20260812 06:17:56.316558 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: LogGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:56.317059 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:56.337553 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.020s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.338160 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6): 447 bytes on disk
I20260812 06:17:56.338629 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: UndoDeltaBlockGCOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.339260 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:56.559931 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.221s	user 0.140s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4303,"lbm_read_time_us":13803,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35814,"lbm_writes_lt_1ms":643,"mutex_wait_us":1304,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:17:56.560670 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=18.063937
I20260812 06:17:56.630466 15716 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.914s	user 1.809s	sys 0.138s
I20260812 06:17:56.634222 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.073s	user 0.036s	sys 0.026s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29027,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:56.634660 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=2.188937
I20260812 06:17:56.644518 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: FlushDeltaMemStoresOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.645045 15984 maintenance_manager.cc:419] P 9fb9a1e9fa344951aa299fb273e43230: Scheduling MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6): perf score=1.000000
I20260812 06:17:56.698156 15716 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:17:56.698838 15716 tablet_server.cc:179] TabletServer@127.15.89.1:0 shutting down...
I20260812 06:17:56.792069 15878 maintenance_manager.cc:643] P 9fb9a1e9fa344951aa299fb273e43230: MajorDeltaCompactionOp(4ff2406a29b5426b8d67da758a78c1e6) complete. Timing: real 0.147s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_hit":240,"cfile_cache_hit_bytes":9808311,"cfile_cache_miss":392,"cfile_cache_miss_bytes":19068792,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":425,"lbm_read_time_us":8338,"lbm_reads_lt_1ms":424,"lbm_write_time_us":29753,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":62720,"update_count":3000}
I20260812 06:17:56.792903 15716 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:56.793334 15716 tablet_replica.cc:333] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230: stopping tablet replica
I20260812 06:17:56.793594 15716 raft_consensus.cc:2243] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:56.793835 15716 raft_consensus.cc:2272] T 4ff2406a29b5426b8d67da758a78c1e6 P 9fb9a1e9fa344951aa299fb273e43230 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:56.810657 15716 tablet_server.cc:196] TabletServer@127.15.89.1:0 shutdown complete.
I20260812 06:17:56.850101 15716 master.cc:562] Master@127.15.89.62:36397 shutting down...
I20260812 06:17:56.853765 15716 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:56.853946 15716 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:56.854008 15716 tablet_replica.cc:333] T 00000000000000000000000000000000 P b6c691791c4245a9945808d1065a6689: stopping tablet replica
I20260812 06:17:56.866483 15716 master.cc:584] Master@127.15.89.62:36397 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5539 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:56.976578 15716 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.89.62:35369
I20260812 06:17:56.976994 15716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:56.979409 15716 server_base.cc:1061] running on GCE node
W20260812 06:17:56.979398 16037 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:56.979355 16039 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:56.979398 16042 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:56.979822 15716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:56.979866 15716 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:56.979882 15716 hybrid_clock.cc:648] HybridClock initialized: now 1786515476979881 us; error 0 us; skew 500 ppm
I20260812 06:17:56.980738 15716 webserver.cc:533] Webserver started at http://127.15.89.62:36381/ using document root <none> and password file <none>
I20260812 06:17:56.980923 15716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:56.980979 15716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:56.981084 15716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:56.981521 15716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/master-0-root/instance:
uuid: "61a07d7f8c6248c5bcf6bd06823ec499"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-92m1"
I20260812 06:17:56.983081 15716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:56.984359 16058 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:56.984665 15716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:56.984745 15716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/master-0-root
uuid: "61a07d7f8c6248c5bcf6bd06823ec499"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-92m1"
I20260812 06:17:56.984807 15716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-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:56.996268 15716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:56.996621 15716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.000993 15716 rpc_server.cc:307] RPC server started. Bound to: 127.15.89.62:35369
I20260812 06:17:57.002779 16145 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:57.007287 16144 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.89.62:35369 every 8 connection(s)
I20260812 06:17:57.008507 16145 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499: Bootstrap starting.
I20260812 06:17:57.009414 16145 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.010615 16145 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499: No bootstrap required, opened a new log
I20260812 06:17:57.011085 16145 raft_consensus.cc:359] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER }
I20260812 06:17:57.011179 16145 raft_consensus.cc:385] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.011286 16145 raft_consensus.cc:740] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 61a07d7f8c6248c5bcf6bd06823ec499, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.011489 16145 consensus_queue.cc:260] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [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: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER }
I20260812 06:17:57.011571 16145 raft_consensus.cc:399] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.011642 16145 raft_consensus.cc:493] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.011711 16145 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.012503 16145 raft_consensus.cc:515] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER }
I20260812 06:17:57.012687 16145 leader_election.cc:304] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [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: 61a07d7f8c6248c5bcf6bd06823ec499; no voters: 
I20260812 06:17:57.012941 16145 leader_election.cc:290] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.013121 16150 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.013334 16150 raft_consensus.cc:697] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 1 LEADER]: Becoming Leader. State: Replica: 61a07d7f8c6248c5bcf6bd06823ec499, State: Running, Role: LEADER
I20260812 06:17:57.013484 16150 consensus_queue.cc:237] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [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: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER }
I20260812 06:17:57.013545 16145 sys_catalog.cc:565] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:57.014001 16152 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER } }
I20260812 06:17:57.014103 16152 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.014057 16153 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 61a07d7f8c6248c5bcf6bd06823ec499. Latest consensus state: current_term: 1 leader_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61a07d7f8c6248c5bcf6bd06823ec499" member_type: VOTER } }
I20260812 06:17:57.014153 16153 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:57.014915 16157 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:57.016150 16157 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:57.016387 15716 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:57.018118 16157 catalog_manager.cc:1383] Generated new cluster ID: 0f3572cf66854716ae3b75319e574853
I20260812 06:17:57.018183 16157 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:57.027542 16157 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:57.028203 16157 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:57.035451 16157 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499: Generated new TSK 0
I20260812 06:17:57.035697 16157 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:57.049073 15716 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:57.051591 16183 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:57.051692 15716 server_base.cc:1061] running on GCE node
W20260812 06:17:57.051786 16184 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:57.051855 16186 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:57.052043 15716 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:57.052119 15716 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:57.052145 15716 hybrid_clock.cc:648] HybridClock initialized: now 1786515477052143 us; error 0 us; skew 500 ppm
I20260812 06:17:57.052973 15716 webserver.cc:533] Webserver started at http://127.15.89.1:34591/ using document root <none> and password file <none>
I20260812 06:17:57.053169 15716 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:57.053247 15716 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:57.053331 15716 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:57.053782 15716 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/instance:
uuid: "005165d737b1473a8f7bb762123e154a"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-92m1"
I20260812 06:17:57.055460 15716 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:57.056463 16193 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:57.056747 15716 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:57.056838 15716 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root
uuid: "005165d737b1473a8f7bb762123e154a"
format_stamp: "Formatted at 2026-08-12 06:17:57 on dist-test-slave-92m1"
I20260812 06:17:57.056927 15716 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-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:57.072767 15716 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:57.073187 15716 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:57.073453 15716 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:57.073951 15716 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:57.074025 15716 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.074087 15716 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:57.074117 15716 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:57.078581 15716 rpc_server.cc:307] RPC server started. Bound to: 127.15.89.1:42431
I20260812 06:17:57.079425 16300 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.89.1:42431 every 8 connection(s)
I20260812 06:17:57.088866 16303 heartbeater.cc:344] Connected to a master server at 127.15.89.62:35369
I20260812 06:17:57.089012 16303 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:57.089286 16303 heartbeater.cc:507] Master 127.15.89.62:35369 requested a full tablet report, sending...
I20260812 06:17:57.089967 16085 ts_manager.cc:194] Registered new tserver with Master: 005165d737b1473a8f7bb762123e154a (127.15.89.1:42431)
I20260812 06:17:57.090677 15716 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011258889s
I20260812 06:17:57.090693 16085 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55722
I20260812 06:17:57.098167 16085 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55724:
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:57.107167 16246 tablet_service.cc:1511] Processing CreateTablet for tablet e8fda725943046b5bf9fc9a6962f9843 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f6259932334b4cc49ab8c53a8010fedc]), partition=
I20260812 06:17:57.107518 16246 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e8fda725943046b5bf9fc9a6962f9843. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:57.109493 16320 tablet_bootstrap.cc:492] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Bootstrap starting.
I20260812 06:17:57.110370 16320 tablet_bootstrap.cc:654] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:57.111553 16320 tablet_bootstrap.cc:492] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: No bootstrap required, opened a new log
I20260812 06:17:57.111671 16320 ts_tablet_manager.cc:1403] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:57.112094 16320 raft_consensus.cc:359] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "005165d737b1473a8f7bb762123e154a" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 42431 } }
I20260812 06:17:57.112206 16320 raft_consensus.cc:385] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:57.112260 16320 raft_consensus.cc:740] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 005165d737b1473a8f7bb762123e154a, State: Initialized, Role: FOLLOWER
I20260812 06:17:57.112465 16320 consensus_queue.cc:260] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [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: "005165d737b1473a8f7bb762123e154a" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 42431 } }
I20260812 06:17:57.112599 16320 raft_consensus.cc:399] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:57.112661 16320 raft_consensus.cc:493] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:57.112742 16320 raft_consensus.cc:3060] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:57.113543 16320 raft_consensus.cc:515] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "005165d737b1473a8f7bb762123e154a" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 42431 } }
I20260812 06:17:57.113698 16320 leader_election.cc:304] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [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: 005165d737b1473a8f7bb762123e154a; no voters: 
I20260812 06:17:57.113910 16320 leader_election.cc:290] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:57.114063 16327 raft_consensus.cc:2804] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:57.114311 16320 ts_tablet_manager.cc:1434] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:57.114344 16303 heartbeater.cc:499] Master 127.15.89.62:35369 was elected leader, sending a full tablet report...
I20260812 06:17:57.114341 16327 raft_consensus.cc:697] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 1 LEADER]: Becoming Leader. State: Replica: 005165d737b1473a8f7bb762123e154a, State: Running, Role: LEADER
I20260812 06:17:57.114612 16327 consensus_queue.cc:237] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [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: "005165d737b1473a8f7bb762123e154a" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 42431 } }
I20260812 06:17:57.116252 16085 catalog_manager.cc:5719] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a reported cstate change: term changed from 0 to 1, leader changed from <none> to 005165d737b1473a8f7bb762123e154a (127.15.89.1). New cstate: current_term: 1 leader_uuid: "005165d737b1473a8f7bb762123e154a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "005165d737b1473a8f7bb762123e154a" member_type: VOTER last_known_addr { host: "127.15.89.1" port: 42431 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:57.177357 15716 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.012s	sys 0.011s
I20260812 06:17:57.329972 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843): perf score=19.054940
I20260812 06:17:57.486202 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.156s	user 0.115s	sys 0.040s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":701,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38372,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:57.487064 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 20743880 bytes of WAL
I20260812 06:17:57.487323 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 2 log segments from log reader
I20260812 06:17:57.487377 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000001 (ops 1-6)
I20260812 06:17:57.487471 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000002 (ops 7-11)
I20260812 06:17:57.493986 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.007s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:57.494511 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843): 16411395 bytes on disk
I20260812 06:17:57.495265 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.000s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.495784 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:57.511979 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.512416 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:57.668156 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.156s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":572,"lbm_read_time_us":10951,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23018,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":325,"threads_started":5,"update_count":2000}
I20260812 06:17:57.668829 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=11.118625
I20260812 06:17:57.707712 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.039s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16302,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:57.708228 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:57.725031 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.017s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.725587 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:57.746374 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.746984 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:57.938442 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.191s	user 0.136s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":568,"lbm_read_time_us":12477,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29022,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:57.939110 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=14.095187
I20260812 06:17:57.984148 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.045s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19843,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.984678 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:57.997709 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.998422 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:58.169525 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.171s	user 0.113s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":9357,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29637,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2500}
I20260812 06:17:58.170222 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=11.118625
I20260812 06:17:58.205953 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.036s	user 0.012s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15977,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:58.207643 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:58.223595 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5388,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.224148 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:58.352114 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.128s	user 0.097s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":8795,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27073,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:17:58.352880 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=10.126437
I20260812 06:17:58.401376 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.048s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16291,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.401882 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:58.416885 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.417416 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:58.539294 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.122s	user 0.093s	sys 0.028s 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":813,"lbm_read_time_us":8973,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22109,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.540005 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=10.126437
I20260812 06:17:58.594512 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.054s	user 0.023s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17551,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:58.595100 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:58.609508 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.609927 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:58.800994 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.191s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":10379,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29456,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:58.801537 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=14.095187
I20260812 06:17:58.854226 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.052s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20301,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.854727 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:58.865054 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.865495 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:58.898156 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1992,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:58.898794 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 121006430 bytes of WAL
I20260812 06:17:58.899029 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 12 log segments from log reader
I20260812 06:17:58.899075 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000003 (ops 12-16)
I20260812 06:17:58.899127 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000004 (ops 17-21)
I20260812 06:17:58.899169 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000005 (ops 22-26)
I20260812 06:17:58.899221 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000006 (ops 27-31)
I20260812 06:17:58.899264 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000007 (ops 32-36)
I20260812 06:17:58.899304 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000008 (ops 37-41)
I20260812 06:17:58.899343 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000009 (ops 42-46)
I20260812 06:17:58.899382 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000010 (ops 47-50)
I20260812 06:17:58.899420 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000011 (ops 51-55)
I20260812 06:17:58.899466 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000012 (ops 56-60)
I20260812 06:17:58.899494 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000013 (ops 61-65)
I20260812 06:17:58.899530 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000014 (ops 66-70)
I20260812 06:17:58.924990 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:58.925544 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843): 483 bytes on disk
I20260812 06:17:58.926009 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.927559 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=3.181125
I20260812 06:17:58.957083 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.029s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4307782,"delete_count":0,"lbm_write_time_us":7581,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:17:58.957589 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 11564875 bytes of WAL
I20260812 06:17:58.957862 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 1 log segments from log reader
I20260812 06:17:58.957938 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000015 (ops 71-74)
I20260812 06:17:58.960196 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:58.960479 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:58.970485 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3866,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:17:58.970881 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:59.215497 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.244s	user 0.162s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1126,"lbm_read_time_us":16651,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38649,"lbm_writes_lt_1ms":743,"mutex_wait_us":662,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:59.216456 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=18.063937
I20260812 06:17:59.286428 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.070s	user 0.035s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26042,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:59.286955 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:59.302409 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.303027 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:59.526839 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.224s	user 0.132s	sys 0.080s 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":710,"lbm_read_time_us":14875,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36263,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:17:59.527604 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=18.063937
I20260812 06:17:59.597836 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.070s	user 0.026s	sys 0.032s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28268,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:59.598377 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:59.608464 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.608906 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:17:59.822751 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.214s	user 0.134s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":16002,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35752,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":3000}
I20260812 06:17:59.823853 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=15.087375
I20260812 06:17:59.876196 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.052s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":20514,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:59.876960 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:59.894012 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.017s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6920,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.894479 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:17:59.907857 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5308,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:59.908281 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:00.107752 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.199s	user 0.126s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":921,"lbm_read_time_us":14561,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33082,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:00.108330 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=15.087375
I20260812 06:18:00.156220 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20915,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:00.157012 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:00.173195 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.173740 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:00.360074 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.186s	user 0.142s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":941,"lbm_read_time_us":13783,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31307,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:18:00.360759 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=15.087375
I20260812 06:18:00.413493 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23853,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:00.414032 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:00.426296 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4913,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.426783 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:00.457801 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1483,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1479,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:00.458477 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 116849534 bytes of WAL
I20260812 06:18:00.458700 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 12 log segments from log reader
I20260812 06:18:00.458758 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000016 (ops 75-79)
I20260812 06:18:00.458811 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000017 (ops 80-84)
I20260812 06:18:00.458870 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000018 (ops 85-89)
I20260812 06:18:00.458918 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000019 (ops 90-94)
I20260812 06:18:00.458956 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000020 (ops 95-98)
I20260812 06:18:00.458994 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000021 (ops 99-103)
I20260812 06:18:00.459031 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000022 (ops 104-108)
I20260812 06:18:00.459069 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000023 (ops 109-112)
I20260812 06:18:00.459106 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000024 (ops 113-117)
I20260812 06:18:00.459141 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000025 (ops 118-122)
I20260812 06:18:00.459178 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000026 (ops 123-126)
I20260812 06:18:00.459264 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000027 (ops 127-131)
I20260812 06:18:00.486032 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:00.486534 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843): 482 bytes on disk
I20260812 06:18:00.487043 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.487581 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=6.157687
I20260812 06:18:00.510867 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9868,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:00.511489 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 12017954 bytes of WAL
I20260812 06:18:00.511752 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 1 log segments from log reader
I20260812 06:18:00.511848 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000028 (ops 132-136)
I20260812 06:18:00.515750 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:00.516232 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:00.758891 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.242s	user 0.167s	sys 0.068s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979619,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":949,"lbm_read_time_us":16236,"lbm_reads_lt_1ms":765,"lbm_write_time_us":41232,"lbm_writes_lt_1ms":743,"mutex_wait_us":83,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:18:00.759650 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=22.032687
I20260812 06:18:00.841710 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.082s	user 0.050s	sys 0.028s Metrics: {"bytes_written":24614724,"delete_count":0,"lbm_write_time_us":37200,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":602,"reinsert_count":0,"update_count":3000}
I20260812 06:18:00.842414 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=3.181125
I20260812 06:18:00.856105 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:00.856634 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:00.871045 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5162,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:00.871631 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:01.093593 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.222s	user 0.160s	sys 0.052s Metrics: {"cfile_cache_miss":833,"cfile_cache_miss_bytes":37082032,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":258,"lbm_read_time_us":16273,"lbm_reads_lt_1ms":873,"lbm_write_time_us":44834,"lbm_writes_lt_1ms":843,"mutex_wait_us":49,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":4000}
I20260812 06:18:01.094259 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=18.063937
I20260812 06:18:01.155129 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.061s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27484,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:01.155807 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.170946 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5926,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.171543 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:01.333410 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.162s	user 0.124s	sys 0.037s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":405,"lbm_read_time_us":12020,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34399,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":3000}
I20260812 06:18:01.334481 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=14.095187
I20260812 06:18:01.382443 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.048s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19402,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.383955 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.394788 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.395282 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:01.544071 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.149s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":12173,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26716,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":2500}
I20260812 06:18:01.544826 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=10.126437
I20260812 06:18:01.582206 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.037s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17177,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.582710 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.598555 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.599175 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:01.753648 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.154s	user 0.105s	sys 0.043s 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":749,"lbm_read_time_us":10252,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25283,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:01.754263 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=11.118625
I20260812 06:18:01.798928 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.044s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18290,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:01.799479 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.829483 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.030s	user 0.006s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.830082 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.840227 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.840719 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:01.882588 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushMRSOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.042s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1421,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1590,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:01.883396 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling LogGCOp(e8fda725943046b5bf9fc9a6962f9843): free 112239552 bytes of WAL
I20260812 06:18:01.883631 16202 log_reader.cc:385] T e8fda725943046b5bf9fc9a6962f9843: removed 11 log segments from log reader
I20260812 06:18:01.883677 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000029 (ops 137-141)
I20260812 06:18:01.883702 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000030 (ops 142-146)
I20260812 06:18:01.883771 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000031 (ops 147-150)
I20260812 06:18:01.883816 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000032 (ops 151-155)
I20260812 06:18:01.883863 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000033 (ops 156-160)
I20260812 06:18:01.883915 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000034 (ops 161-165)
I20260812 06:18:01.883983 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000035 (ops 166-170)
I20260812 06:18:01.884027 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000036 (ops 171-175)
I20260812 06:18:01.884069 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000037 (ops 176-180)
I20260812 06:18:01.884109 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000038 (ops 181-185)
I20260812 06:18:01.884150 16202 log.cc:1079] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: Deleting log segment in path: /tmp/dist-test-taskZZ9wQm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515471414138-15716-0/minicluster-data/ts-0-root/wals/e8fda725943046b5bf9fc9a6962f9843/wal-000000039 (ops 186-190)
I20260812 06:18:01.908737 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: LogGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:01.909152 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843): 462 bytes on disk
I20260812 06:18:01.909590 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: UndoDeltaBlockGCOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.910140 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.933571 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.023s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.934089 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=2.188937
I20260812 06:18:01.944855 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.945468 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843): perf score=1.000000
I20260812 06:18:02.089346 15716 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.912s	user 1.824s	sys 0.164s
I20260812 06:18:02.174757 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: MajorDeltaCompactionOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.229s	user 0.133s	sys 0.096s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979861,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1284,"lbm_read_time_us":15964,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40123,"lbm_writes_lt_1ms":743,"mutex_wait_us":92,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:18:02.175613 16304 maintenance_manager.cc:419] P 005165d737b1473a8f7bb762123e154a: Scheduling FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843): perf score=10.126437
I20260812 06:18:02.184515 15716 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.002s	sys 0.000s
I20260812 06:18:02.185017 15716 tablet_server.cc:179] TabletServer@127.15.89.1:0 shutting down...
I20260812 06:18:02.213361 16202 maintenance_manager.cc:643] P 005165d737b1473a8f7bb762123e154a: FlushDeltaMemStoresOp(e8fda725943046b5bf9fc9a6962f9843) complete. Timing: real 0.038s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:02.214013 15716 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:02.214277 15716 tablet_replica.cc:333] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a: stopping tablet replica
I20260812 06:18:02.215960 15716 raft_consensus.cc:2243] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.216163 15716 raft_consensus.cc:2272] T e8fda725943046b5bf9fc9a6962f9843 P 005165d737b1473a8f7bb762123e154a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.229766 15716 tablet_server.cc:196] TabletServer@127.15.89.1:0 shutdown complete.
I20260812 06:18:02.232951 15716 master.cc:562] Master@127.15.89.62:35369 shutting down...
I20260812 06:18:02.236317 15716 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:02.236467 15716 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:02.236516 15716 tablet_replica.cc:333] T 00000000000000000000000000000000 P 61a07d7f8c6248c5bcf6bd06823ec499: stopping tablet replica
I20260812 06:18:02.248777 15716 master.cc:584] Master@127.15.89.62:35369 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5369 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10910 ms total)

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