[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:35.841355  5149 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.7.126:42869
I20260812 06:18:35.842275  5149 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:35.842828  5149 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:35.848781  5155 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:35.848896  5157 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:35.848958  5149 server_base.cc:1061] running on GCE node
W20260812 06:18:35.849098  5163 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:35.849548  5149 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:35.849635  5149 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:35.849664  5149 hybrid_clock.cc:648] HybridClock initialized: now 1786515515849663 us; error 0 us; skew 500 ppm
I20260812 06:18:35.851248  5149 webserver.cc:533] Webserver started at http://127.5.7.126:46119/ using document root <none> and password file <none>
I20260812 06:18:35.851692  5149 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:35.851745  5149 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:35.851931  5149 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:35.853430  5149 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/master-0-root/instance:
uuid: "7eb07ba368f742b9a78e5aba50b867b2"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-cvwc"
I20260812 06:18:35.856539  5149 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:18:35.858385  5170 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:35.859297  5149 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:18:35.859385  5149 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/master-0-root
uuid: "7eb07ba368f742b9a78e5aba50b867b2"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-cvwc"
I20260812 06:18:35.859455  5149 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:35.881001  5149 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:35.881538  5149 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:35.881666  5149 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:35.888648  5149 rpc_server.cc:307] RPC server started. Bound to: 127.5.7.126:42869
I20260812 06:18:35.888721  5266 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.7.126:42869 every 8 connection(s)
I20260812 06:18:35.890832  5267 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:35.896013  5267 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: Bootstrap starting.
I20260812 06:18:35.898213  5267 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:35.899063  5267 log.cc:826] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:35.900624  5267 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: No bootstrap required, opened a new log
I20260812 06:18:35.903538  5267 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER }
I20260812 06:18:35.903708  5267 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:35.903775  5267 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7eb07ba368f742b9a78e5aba50b867b2, State: Initialized, Role: FOLLOWER
I20260812 06:18:35.904320  5267 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [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: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER }
I20260812 06:18:35.904469  5267 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:35.904531  5267 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:35.904646  5267 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:35.905366  5267 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER }
I20260812 06:18:35.905781  5267 leader_election.cc:304] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [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: 7eb07ba368f742b9a78e5aba50b867b2; no voters: 
I20260812 06:18:35.906066  5267 leader_election.cc:290] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:35.906178  5270 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:35.906385  5270 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 1 LEADER]: Becoming Leader. State: Replica: 7eb07ba368f742b9a78e5aba50b867b2, State: Running, Role: LEADER
I20260812 06:18:35.906749  5270 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [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: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER }
I20260812 06:18:35.906962  5267 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:35.908512  5273 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7eb07ba368f742b9a78e5aba50b867b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER } }
I20260812 06:18:35.908499  5274 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7eb07ba368f742b9a78e5aba50b867b2. Latest consensus state: current_term: 1 leader_uuid: "7eb07ba368f742b9a78e5aba50b867b2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7eb07ba368f742b9a78e5aba50b867b2" member_type: VOTER } }
I20260812 06:18:35.908641  5274 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:35.908641  5273 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:35.909052  5149 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:35.911660  5293 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:35.911744  5293 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:35.911851  5292 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:35.912606  5292 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:35.917171  5292 catalog_manager.cc:1383] Generated new cluster ID: 5595996e8099412e974e8393d25a32c6
I20260812 06:18:35.917232  5292 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:35.930337  5292 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:35.931399  5292 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:35.940789  5292 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: Generated new TSK 0
I20260812 06:18:35.941385  5292 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:35.973887  5149 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:35.976420  5300 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:35.976508  5301 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:35.976600  5304 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:35.976878  5149 server_base.cc:1061] running on GCE node
I20260812 06:18:35.977044  5149 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:35.977089  5149 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:35.977109  5149 hybrid_clock.cc:648] HybridClock initialized: now 1786515515977109 us; error 0 us; skew 500 ppm
I20260812 06:18:35.977982  5149 webserver.cc:533] Webserver started at http://127.5.7.65:41823/ using document root <none> and password file <none>
I20260812 06:18:35.978144  5149 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:35.978193  5149 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:35.978268  5149 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:35.978652  5149 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/instance:
uuid: "25462f4044f94f4093116f2628da3fbb"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-cvwc"
I20260812 06:18:35.980080  5149 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:35.980976  5313 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:35.981196  5149 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:35.981261  5149 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root
uuid: "25462f4044f94f4093116f2628da3fbb"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-cvwc"
I20260812 06:18:35.981326  5149 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.009218  5149 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.009637  5149 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.010107  5149 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:36.010922  5149 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:36.010975  5149 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.011018  5149 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:36.011046  5149 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.016430  5149 rpc_server.cc:307] RPC server started. Bound to: 127.5.7.65:45411
I20260812 06:18:36.016482  5403 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.7.65:45411 every 8 connection(s)
I20260812 06:18:36.028183  5404 heartbeater.cc:344] Connected to a master server at 127.5.7.126:42869
I20260812 06:18:36.028409  5404 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:36.028836  5404 heartbeater.cc:507] Master 127.5.7.126:42869 requested a full tablet report, sending...
I20260812 06:18:36.030212  5201 ts_manager.cc:194] Registered new tserver with Master: 25462f4044f94f4093116f2628da3fbb (127.5.7.65:45411)
I20260812 06:18:36.030323  5149 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013332143s
I20260812 06:18:36.031395  5201 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35330
I20260812 06:18:36.039237  5201 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35346:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:36.051765  5353 tablet_service.cc:1511] Processing CreateTablet for tablet 1b5eb0406de5466591bee06bfef81526 (DEFAULT_TABLE table=heavy-update-compaction-test [id=00233be073d94fdd9d635c834600be76]), partition=
I20260812 06:18:36.052147  5353 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1b5eb0406de5466591bee06bfef81526. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.054672  5428 tablet_bootstrap.cc:492] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Bootstrap starting.
I20260812 06:18:36.055508  5428 tablet_bootstrap.cc:654] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.056618  5428 tablet_bootstrap.cc:492] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: No bootstrap required, opened a new log
I20260812 06:18:36.056704  5428 ts_tablet_manager.cc:1403] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:36.057126  5428 raft_consensus.cc:359] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25462f4044f94f4093116f2628da3fbb" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 45411 } }
I20260812 06:18:36.057222  5428 raft_consensus.cc:385] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.057256  5428 raft_consensus.cc:740] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 25462f4044f94f4093116f2628da3fbb, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.057384  5428 consensus_queue.cc:260] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [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: "25462f4044f94f4093116f2628da3fbb" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 45411 } }
I20260812 06:18:36.057468  5428 raft_consensus.cc:399] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.057507  5428 raft_consensus.cc:493] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.057555  5428 raft_consensus.cc:3060] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.058286  5428 raft_consensus.cc:515] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25462f4044f94f4093116f2628da3fbb" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 45411 } }
I20260812 06:18:36.058405  5428 leader_election.cc:304] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [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: 25462f4044f94f4093116f2628da3fbb; no voters: 
I20260812 06:18:36.058604  5428 leader_election.cc:290] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.058714  5430 raft_consensus.cc:2804] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.058918  5428 ts_tablet_manager.cc:1434] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:36.058938  5430 raft_consensus.cc:697] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 1 LEADER]: Becoming Leader. State: Replica: 25462f4044f94f4093116f2628da3fbb, State: Running, Role: LEADER
I20260812 06:18:36.059122  5404 heartbeater.cc:499] Master 127.5.7.126:42869 was elected leader, sending a full tablet report...
I20260812 06:18:36.059144  5430 consensus_queue.cc:237] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [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: "25462f4044f94f4093116f2628da3fbb" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 45411 } }
I20260812 06:18:36.061654  5199 catalog_manager.cc:5719] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb reported cstate change: term changed from 0 to 1, leader changed from <none> to 25462f4044f94f4093116f2628da3fbb (127.5.7.65). New cstate: current_term: 1 leader_uuid: "25462f4044f94f4093116f2628da3fbb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25462f4044f94f4093116f2628da3fbb" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 45411 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:36.116220  5149 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.025s	sys 0.000s
I20260812 06:18:36.267403  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushMRSOp(1b5eb0406de5466591bee06bfef81526): perf score=23.023690
I20260812 06:18:36.456189  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushMRSOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.188s	user 0.117s	sys 0.062s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":1408,"delete_count":0,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":746,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45617,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":115,"threads_started":1,"update_count":1500}
I20260812 06:18:36.457101  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling LogGCOp(1b5eb0406de5466591bee06bfef81526): free 20743880 bytes of WAL
I20260812 06:18:36.457362  5321 log_reader.cc:385] T 1b5eb0406de5466591bee06bfef81526: removed 2 log segments from log reader
I20260812 06:18:36.457415  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000001 (ops 1-6)
I20260812 06:18:36.457473  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000002 (ops 7-11)
I20260812 06:18:36.460534  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: LogGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.460795  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:36.470335  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.470651  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526): 20513816 bytes on disk
I20260812 06:18:36.471120  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.471460  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:36.621735  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.150s	user 0.099s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":9272,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22751,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":271,"threads_started":5,"update_count":2000}
I20260812 06:18:36.622170  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:36.661954  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.040s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11689,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.662428  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:36.672129  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.672744  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:36.781831  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.109s	user 0.096s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":537,"lbm_read_time_us":7365,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20245,"lbm_writes_lt_1ms":443,"mutex_wait_us":90,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:36.782303  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:36.825606  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.043s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13546,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.826123  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:36.835865  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.836328  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:36.950402  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.114s	user 0.102s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":562,"lbm_read_time_us":8689,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19900,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2000}
I20260812 06:18:36.950989  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:36.997196  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.046s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15583,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.997677  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:37.007397  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.007838  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:37.150913  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.143s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":9283,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25113,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:37.151433  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:37.195238  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.044s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.195719  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:37.205504  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.206156  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:37.322693  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.116s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":7324,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22048,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:37.323174  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:37.357982  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.035s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.358500  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:37.368566  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.369043  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:37.489123  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.120s	user 0.090s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":7470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23879,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:18:37.489631  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:37.538906  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.049s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15933,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.539479  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:37.550397  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.550829  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushMRSOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:37.588178  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushMRSOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.037s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":164,"dirs.run_wall_time_us":1033,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1298,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:37.588925  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling LogGCOp(1b5eb0406de5466591bee06bfef81526): free 112239255 bytes of WAL
I20260812 06:18:37.589133  5321 log_reader.cc:385] T 1b5eb0406de5466591bee06bfef81526: removed 11 log segments from log reader
I20260812 06:18:37.589176  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000003 (ops 12-16)
I20260812 06:18:37.589206  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000004 (ops 17-20)
I20260812 06:18:37.589238  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000005 (ops 21-25)
I20260812 06:18:37.589269  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000006 (ops 26-30)
I20260812 06:18:37.589300  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000007 (ops 31-35)
I20260812 06:18:37.589331  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000008 (ops 36-40)
I20260812 06:18:37.589363  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000009 (ops 41-45)
I20260812 06:18:37.589394  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000010 (ops 46-50)
I20260812 06:18:37.589426  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000011 (ops 51-55)
I20260812 06:18:37.589458  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000012 (ops 56-60)
I20260812 06:18:37.589489  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000013 (ops 61-65)
I20260812 06:18:37.608017  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: LogGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:18:37.608536  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526): 447 bytes on disk
I20260812 06:18:37.608948  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.609690  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=3.181125
I20260812 06:18:37.628363  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.018s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.628805  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:37.637641  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3133,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.638154  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:37.836598  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.198s	user 0.127s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":160,"lbm_read_time_us":13436,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31590,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24192,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:18:37.837175  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=14.095187
I20260812 06:18:37.876821  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.039s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.877249  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.014761  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.137s	user 0.090s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":171,"lbm_read_time_us":10493,"lbm_reads_lt_1ms":467,"lbm_write_time_us":19868,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:38.015214  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.049526  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14478,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.049968  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.060482  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.060874  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.171864  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.111s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":7765,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20070,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2000}
I20260812 06:18:38.172319  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.215142  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.043s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15081,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.215638  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.225428  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.226022  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.345731  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.120s	user 0.086s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":9643,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20633,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:38.346186  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.387902  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.042s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15639,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.388324  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.397964  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.398442  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.520730  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.122s	user 0.089s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":10005,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21279,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:38.521340  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.564920  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.043s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13583,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.565479  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.576592  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.577142  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.730412  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.153s	user 0.113s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":515,"lbm_read_time_us":10992,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25225,"lbm_writes_lt_1ms":443,"mutex_wait_us":248,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:38.731024  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.769011  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.038s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15138,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:38.769505  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.778978  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.779500  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.904965  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.125s	user 0.086s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":7740,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24335,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:38.905553  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:38.944140  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.038s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14777,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:38.944636  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:38.954097  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.954502  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushMRSOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:38.982568  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushMRSOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":1015,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1409,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:38.983230  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling LogGCOp(1b5eb0406de5466591bee06bfef81526): free 124710298 bytes of WAL
I20260812 06:18:38.983438  5321 log_reader.cc:385] T 1b5eb0406de5466591bee06bfef81526: removed 12 log segments from log reader
I20260812 06:18:38.983486  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000014 (ops 66-70)
I20260812 06:18:38.983515  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000015 (ops 71-75)
I20260812 06:18:38.983544  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000016 (ops 76-80)
I20260812 06:18:38.983577  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000017 (ops 81-85)
I20260812 06:18:38.983609  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000018 (ops 86-90)
I20260812 06:18:38.983640  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000019 (ops 91-95)
I20260812 06:18:38.983672  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000020 (ops 96-100)
I20260812 06:18:38.983702  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000021 (ops 101-105)
I20260812 06:18:38.983733  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000022 (ops 106-110)
I20260812 06:18:38.983763  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000023 (ops 111-115)
I20260812 06:18:38.983793  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000024 (ops 116-120)
I20260812 06:18:38.983824  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000025 (ops 121-125)
I20260812 06:18:39.004601  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: LogGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:39.005048  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=3.181125
I20260812 06:18:39.018787  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:39.019225  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling LogGCOp(1b5eb0406de5466591bee06bfef81526): free 12017991 bytes of WAL
I20260812 06:18:39.019425  5321 log_reader.cc:385] T 1b5eb0406de5466591bee06bfef81526: removed 1 log segments from log reader
I20260812 06:18:39.019481  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000026 (ops 126-130)
I20260812 06:18:39.021926  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: LogGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:39.022207  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526): 473 bytes on disk
I20260812 06:18:39.022619  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.023095  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:39.032932  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3392,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.033576  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:39.225100  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.191s	user 0.149s	sys 0.037s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":980,"lbm_read_time_us":12241,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36521,"lbm_writes_lt_1ms":643,"mutex_wait_us":258,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:39.225611  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=15.087375
I20260812 06:18:39.285920  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.060s	user 0.039s	sys 0.018s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":28067,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:18:39.286402  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=6.157687
I20260812 06:18:39.310523  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.024s	user 0.014s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9788,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:39.311152  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:39.506623  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.195s	user 0.159s	sys 0.032s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":842,"lbm_read_time_us":11084,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35666,"lbm_writes_lt_1ms":643,"mutex_wait_us":227,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:39.507210  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=18.063937
I20260812 06:18:39.572865  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.065s	user 0.021s	sys 0.038s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25009,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:39.573330  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:39.583284  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.583705  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:39.780890  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.197s	user 0.138s	sys 0.047s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":12459,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32508,"lbm_writes_lt_1ms":643,"mutex_wait_us":276,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":3000}
I20260812 06:18:39.781533  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=14.095187
I20260812 06:18:39.834424  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.053s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18731,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.835104  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:39.845481  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.846103  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:40.019654  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.173s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":691,"lbm_read_time_us":11280,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29538,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:40.020251  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=11.118625
I20260812 06:18:40.047658  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.027s	user 0.010s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11468,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:40.048506  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:40.059940  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3875,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.060453  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:40.181363  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.121s	user 0.083s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":375,"lbm_read_time_us":7935,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20244,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:18:40.181998  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:40.219820  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.038s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16007,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.220402  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:40.230116  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.230876  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:40.348361  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.117s	user 0.101s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":793,"lbm_read_time_us":8908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19752,"lbm_writes_lt_1ms":443,"mutex_wait_us":250,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:18:40.348941  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=10.126437
I20260812 06:18:40.388326  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.039s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16729,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.388803  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:40.398434  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.399048  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushMRSOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:40.426836  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushMRSOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.028s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1167,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:40.427580  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling LogGCOp(1b5eb0406de5466591bee06bfef81526): free 121006692 bytes of WAL
I20260812 06:18:40.427816  5321 log_reader.cc:385] T 1b5eb0406de5466591bee06bfef81526: removed 12 log segments from log reader
I20260812 06:18:40.427867  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000027 (ops 131-135)
I20260812 06:18:40.427904  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000028 (ops 136-140)
I20260812 06:18:40.427937  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000029 (ops 141-144)
I20260812 06:18:40.427981  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000030 (ops 145-149)
I20260812 06:18:40.428013  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000031 (ops 150-154)
I20260812 06:18:40.428045  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000032 (ops 155-159)
I20260812 06:18:40.428074  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000033 (ops 160-164)
I20260812 06:18:40.428104  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000034 (ops 165-169)
I20260812 06:18:40.428134  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000035 (ops 170-174)
I20260812 06:18:40.428164  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000036 (ops 175-179)
I20260812 06:18:40.428194  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000037 (ops 180-184)
I20260812 06:18:40.428224  5321 log.cc:1079] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/1b5eb0406de5466591bee06bfef81526/wal-000000038 (ops 185-189)
I20260812 06:18:40.448493  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: LogGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:40.448905  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526): 482 bytes on disk
I20260812 06:18:40.449318  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: UndoDeltaBlockGCOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.449990  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=3.181125
I20260812 06:18:40.463723  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:40.464138  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=2.188937
I20260812 06:18:40.476975  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4760,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.477476  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526): perf score=1.000000
I20260812 06:18:40.638049  5149 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.522s	user 1.665s	sys 0.106s
I20260812 06:18:40.640898  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: MajorDeltaCompactionOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.163s	user 0.104s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":260,"lbm_read_time_us":11026,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30624,"lbm_writes_lt_1ms":643,"mutex_wait_us":277,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:40.641353  5407 maintenance_manager.cc:419] P 25462f4044f94f4093116f2628da3fbb: Scheduling FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526): perf score=14.095187
I20260812 06:18:40.665926  5149 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.027s	user 0.004s	sys 0.000s
I20260812 06:18:40.666529  5149 tablet_server.cc:179] TabletServer@127.5.7.65:0 shutting down...
I20260812 06:18:40.678655  5321 maintenance_manager.cc:643] P 25462f4044f94f4093116f2628da3fbb: FlushDeltaMemStoresOp(1b5eb0406de5466591bee06bfef81526) complete. Timing: real 0.037s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:40.679234  5149 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:40.679662  5149 tablet_replica.cc:333] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb: stopping tablet replica
I20260812 06:18:40.679910  5149 raft_consensus.cc:2243] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.680451  5149 raft_consensus.cc:2272] T 1b5eb0406de5466591bee06bfef81526 P 25462f4044f94f4093116f2628da3fbb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.687779  5149 tablet_server.cc:196] TabletServer@127.5.7.65:0 shutdown complete.
I20260812 06:18:40.692555  5149 master.cc:562] Master@127.5.7.126:42869 shutting down...
I20260812 06:18:40.696092  5149 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.696233  5149 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.696306  5149 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7eb07ba368f742b9a78e5aba50b867b2: stopping tablet replica
I20260812 06:18:40.708362  5149 master.cc:584] Master@127.5.7.126:42869 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4936 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:40.777184  5149 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.7.126:34363
I20260812 06:18:40.777540  5149 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.779440  5455 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.779507  5456 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.779567  5149 server_base.cc:1061] running on GCE node
W20260812 06:18:40.779558  5461 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.779852  5149 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.779896  5149 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.779914  5149 hybrid_clock.cc:648] HybridClock initialized: now 1786515520779914 us; error 0 us; skew 500 ppm
I20260812 06:18:40.780655  5149 webserver.cc:533] Webserver started at http://127.5.7.126:40173/ using document root <none> and password file <none>
I20260812 06:18:40.780803  5149 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.780869  5149 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.780947  5149 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.781404  5149 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/master-0-root/instance:
uuid: "d46b0d8e8c0f4a47999906393109a602"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-cvwc"
I20260812 06:18:40.783017  5149 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:40.783877  5467 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.784122  5149 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.784188  5149 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/master-0-root
uuid: "d46b0d8e8c0f4a47999906393109a602"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-cvwc"
I20260812 06:18:40.784246  5149 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.801362  5149 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.801684  5149 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.805292  5149 rpc_server.cc:307] RPC server started. Bound to: 127.5.7.126:34363
I20260812 06:18:40.819792  5553 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.7.126:34363 every 8 connection(s)
I20260812 06:18:40.820202  5554 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.821967  5554 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602: Bootstrap starting.
I20260812 06:18:40.822679  5554 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.823596  5554 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602: No bootstrap required, opened a new log
I20260812 06:18:40.823956  5554 raft_consensus.cc:359] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER }
I20260812 06:18:40.824038  5554 raft_consensus.cc:385] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.824064  5554 raft_consensus.cc:740] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d46b0d8e8c0f4a47999906393109a602, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.824169  5554 consensus_queue.cc:260] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [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: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER }
I20260812 06:18:40.824252  5554 raft_consensus.cc:399] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.824287  5554 raft_consensus.cc:493] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.824321  5554 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.824934  5554 raft_consensus.cc:515] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER }
I20260812 06:18:40.825043  5554 leader_election.cc:304] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [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: d46b0d8e8c0f4a47999906393109a602; no voters: 
I20260812 06:18:40.825184  5554 leader_election.cc:290] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.825296  5558 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.825484  5558 raft_consensus.cc:697] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 1 LEADER]: Becoming Leader. State: Replica: d46b0d8e8c0f4a47999906393109a602, State: Running, Role: LEADER
I20260812 06:18:40.825627  5554 sys_catalog.cc:565] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.825613  5558 consensus_queue.cc:237] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [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: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER }
I20260812 06:18:40.826074  5563 sys_catalog.cc:455] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d46b0d8e8c0f4a47999906393109a602. Latest consensus state: current_term: 1 leader_uuid: "d46b0d8e8c0f4a47999906393109a602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER } }
I20260812 06:18:40.826103  5560 sys_catalog.cc:455] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d46b0d8e8c0f4a47999906393109a602" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d46b0d8e8c0f4a47999906393109a602" member_type: VOTER } }
I20260812 06:18:40.826224  5563 sys_catalog.cc:458] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.826300  5560 sys_catalog.cc:458] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.826782  5568 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.827545  5568 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.827657  5149 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.829312  5568 catalog_manager.cc:1383] Generated new cluster ID: 2bbcdb02900b46bab11c40f9ef5899b3
I20260812 06:18:40.829382  5568 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.865178  5568 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.865769  5568 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.872537  5568 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602: Generated new TSK 0
I20260812 06:18:40.872687  5568 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.892156  5149 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.894039  5586 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.894097  5149 server_base.cc:1061] running on GCE node
W20260812 06:18:40.894078  5591 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.894148  5589 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.894461  5149 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.894505  5149 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.894526  5149 hybrid_clock.cc:648] HybridClock initialized: now 1786515520894525 us; error 0 us; skew 500 ppm
I20260812 06:18:40.895299  5149 webserver.cc:533] Webserver started at http://127.5.7.65:43719/ using document root <none> and password file <none>
I20260812 06:18:40.895429  5149 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.895469  5149 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.895526  5149 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.895867  5149 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/instance:
uuid: "aa45a7c1604741f8a14a24f6a2356963"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-cvwc"
I20260812 06:18:40.897205  5149 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:40.898077  5598 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.898304  5149 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:40.898365  5149 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root
uuid: "aa45a7c1604741f8a14a24f6a2356963"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-cvwc"
I20260812 06:18:40.898432  5149 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.918912  5149 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.919245  5149 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.919520  5149 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.919960  5149 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.919998  5149 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.920038  5149 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.920066  5149 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.924036  5149 rpc_server.cc:307] RPC server started. Bound to: 127.5.7.65:44967
I20260812 06:18:40.924064  5703 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.7.65:44967 every 8 connection(s)
I20260812 06:18:40.928361  5707 heartbeater.cc:344] Connected to a master server at 127.5.7.126:34363
I20260812 06:18:40.928452  5707 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.928627  5707 heartbeater.cc:507] Master 127.5.7.126:34363 requested a full tablet report, sending...
I20260812 06:18:40.929165  5495 ts_manager.cc:194] Registered new tserver with Master: aa45a7c1604741f8a14a24f6a2356963 (127.5.7.65:44967)
I20260812 06:18:40.929876  5495 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48406
I20260812 06:18:40.930121  5149 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005704914s
I20260812 06:18:40.936339  5495 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48408:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:40.944149  5650 tablet_service.cc:1511] Processing CreateTablet for tablet ec354b36c7cc4325973168684e57cff0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=84e7560b23d849b7b54fd9da70e2ac4d]), partition=
I20260812 06:18:40.944389  5650 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ec354b36c7cc4325973168684e57cff0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.946245  5728 tablet_bootstrap.cc:492] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Bootstrap starting.
I20260812 06:18:40.947170  5728 tablet_bootstrap.cc:654] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.948153  5728 tablet_bootstrap.cc:492] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: No bootstrap required, opened a new log
I20260812 06:18:40.948226  5728 ts_tablet_manager.cc:1403] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:40.948613  5728 raft_consensus.cc:359] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa45a7c1604741f8a14a24f6a2356963" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 44967 } }
I20260812 06:18:40.948706  5728 raft_consensus.cc:385] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.948741  5728 raft_consensus.cc:740] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aa45a7c1604741f8a14a24f6a2356963, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.948863  5728 consensus_queue.cc:260] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [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: "aa45a7c1604741f8a14a24f6a2356963" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 44967 } }
I20260812 06:18:40.948930  5728 raft_consensus.cc:399] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.948964  5728 raft_consensus.cc:493] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.949012  5728 raft_consensus.cc:3060] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.949697  5728 raft_consensus.cc:515] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa45a7c1604741f8a14a24f6a2356963" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 44967 } }
I20260812 06:18:40.949872  5728 leader_election.cc:304] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [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: aa45a7c1604741f8a14a24f6a2356963; no voters: 
I20260812 06:18:40.950047  5728 leader_election.cc:290] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.950132  5730 raft_consensus.cc:2804] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.950300  5730 raft_consensus.cc:697] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 1 LEADER]: Becoming Leader. State: Replica: aa45a7c1604741f8a14a24f6a2356963, State: Running, Role: LEADER
I20260812 06:18:40.950354  5707 heartbeater.cc:499] Master 127.5.7.126:34363 was elected leader, sending a full tablet report...
I20260812 06:18:40.950429  5730 consensus_queue.cc:237] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [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: "aa45a7c1604741f8a14a24f6a2356963" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 44967 } }
I20260812 06:18:40.950349  5728 ts_tablet_manager.cc:1434] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:40.951663  5495 catalog_manager.cc:5719] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 reported cstate change: term changed from 0 to 1, leader changed from <none> to aa45a7c1604741f8a14a24f6a2356963 (127.5.7.65). New cstate: current_term: 1 leader_uuid: "aa45a7c1604741f8a14a24f6a2356963" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa45a7c1604741f8a14a24f6a2356963" member_type: VOTER last_known_addr { host: "127.5.7.65" port: 44967 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:41.005551  5149 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.016s	sys 0.006s
I20260812 06:18:41.174846  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushMRSOp(ec354b36c7cc4325973168684e57cff0): perf score=23.023690
I20260812 06:18:41.320806  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushMRSOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.146s	user 0.105s	sys 0.036s Metrics: {"bytes_written":13210027,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":148,"dirs.run_wall_time_us":582,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39941,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":888,"mutex_wait_us":431,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"spinlock_wait_cycles":1408,"update_count":1610}
I20260812 06:18:41.321448  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling LogGCOp(ec354b36c7cc4325973168684e57cff0): free 20743880 bytes of WAL
I20260812 06:18:41.321791  5604 log_reader.cc:385] T ec354b36c7cc4325973168684e57cff0: removed 2 log segments from log reader
I20260812 06:18:41.321895  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000001 (ops 1-6)
I20260812 06:18:41.321969  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000002 (ops 7-11)
I20260812 06:18:41.326128  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: LogGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.004s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:41.326436  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0): 20924066 bytes on disk
I20260812 06:18:41.326849  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.327275  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:41.340106  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.013s	user 0.006s	sys 0.000s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":2688,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:41.340502  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:41.352840  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4610,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.353248  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:41.505605  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.152s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24446506,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":522,"lbm_read_time_us":10517,"lbm_reads_lt_1ms":559,"lbm_write_time_us":25683,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":285,"threads_started":5,"update_count":2450}
I20260812 06:18:41.506211  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:41.552332  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.046s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17403,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.552798  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:41.567077  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.567633  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:41.712431  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.145s	user 0.109s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":554,"lbm_read_time_us":9344,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27658,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:18:41.712986  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=10.126437
I20260812 06:18:41.741433  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.028s	user 0.017s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11875,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.741986  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:41.755800  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.756285  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:41.912660  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.156s	user 0.120s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20754243,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":693,"lbm_read_time_us":10453,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20564,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:18:41.913275  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:41.964718  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.051s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16607,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.965234  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:41.979122  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.979559  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:42.149994  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.170s	user 0.108s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":10769,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25400,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:42.150556  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:42.194048  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.043s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18738,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.194588  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:42.208278  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.208837  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:42.388337  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.179s	user 0.116s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":10080,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30674,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:18:42.389074  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:42.430213  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.041s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17303,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.430790  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:42.446564  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.447391  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushMRSOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:42.480396  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushMRSOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.033s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1084,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1600,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:42.481133  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling LogGCOp(ec354b36c7cc4325973168684e57cff0): free 120100325 bytes of WAL
I20260812 06:18:42.481395  5604 log_reader.cc:385] T ec354b36c7cc4325973168684e57cff0: removed 12 log segments from log reader
I20260812 06:18:42.481451  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000003 (ops 12-16)
I20260812 06:18:42.481498  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000004 (ops 17-20)
I20260812 06:18:42.481535  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000005 (ops 21-25)
I20260812 06:18:42.481572  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000006 (ops 26-30)
I20260812 06:18:42.481609  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000007 (ops 31-35)
I20260812 06:18:42.481647  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000008 (ops 36-40)
I20260812 06:18:42.481684  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000009 (ops 41-45)
I20260812 06:18:42.481741  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000010 (ops 46-50)
I20260812 06:18:42.481779  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000011 (ops 51-54)
I20260812 06:18:42.481815  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000012 (ops 55-59)
I20260812 06:18:42.481850  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000013 (ops 60-64)
I20260812 06:18:42.481887  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000014 (ops 65-68)
I20260812 06:18:42.505415  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: LogGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.024s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:42.505949  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=3.181125
I20260812 06:18:42.528810  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.023s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.529207  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling LogGCOp(ec354b36c7cc4325973168684e57cff0): free 8767118 bytes of WAL
I20260812 06:18:42.529389  5604 log_reader.cc:385] T ec354b36c7cc4325973168684e57cff0: removed 1 log segments from log reader
I20260812 06:18:42.529433  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000015 (ops 69-73)
I20260812 06:18:42.530812  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: LogGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:42.531157  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:42.540359  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.009s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3354,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.540740  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:42.786326  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.245s	user 0.156s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061705,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":154,"lbm_read_time_us":16065,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37671,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13696,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:18:42.786911  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=18.063937
I20260812 06:18:42.852681  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.065s	user 0.028s	sys 0.024s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":23068,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:42.853261  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0): 462 bytes on disk
I20260812 06:18:42.853776  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.854312  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:42.867100  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.867795  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:43.049871  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.182s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959072,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":237,"lbm_read_time_us":13956,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29712,"lbm_writes_lt_1ms":643,"mutex_wait_us":72,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":3000}
I20260812 06:18:43.050446  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:43.103683  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.053s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18558,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.104197  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:43.119644  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.120158  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:43.284087  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.164s	user 0.097s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":508,"lbm_read_time_us":10353,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26052,"lbm_writes_lt_1ms":543,"mutex_wait_us":253,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:18:43.284524  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:43.334177  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.050s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.334714  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:43.344941  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.345517  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:43.528367  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.183s	user 0.113s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":11040,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28276,"lbm_writes_lt_1ms":543,"mutex_wait_us":274,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:43.528887  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:43.583462  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.054s	user 0.018s	sys 0.030s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18504,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.583999  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:43.594519  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.594990  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:43.759563  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.164s	user 0.111s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":401,"lbm_read_time_us":11047,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25285,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:18:43.760006  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=11.118625
I20260812 06:18:43.794018  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.034s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14067,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.794510  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:43.828653  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.034s	user 0.009s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4968,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.829139  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:43.844120  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.844648  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:44.007424  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.163s	user 0.099s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856764,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":273,"lbm_read_time_us":11923,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26139,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:44.008124  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=11.118625
I20260812 06:18:44.042783  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13825,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.043378  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:44.059633  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.016s	user 0.000s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5275,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.060237  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushMRSOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:44.109037  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushMRSOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.049s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":130,"dirs.run_wall_time_us":1003,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1679,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":10624}
I20260812 06:18:44.109947  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=6.157687
I20260812 06:18:44.130586  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.020s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":8220,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:44.131095  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling LogGCOp(ec354b36c7cc4325973168684e57cff0): free 132571347 bytes of WAL
I20260812 06:18:44.131300  5604 log_reader.cc:385] T ec354b36c7cc4325973168684e57cff0: removed 13 log segments from log reader
I20260812 06:18:44.131379  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000016 (ops 74-78)
I20260812 06:18:44.131438  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000017 (ops 79-83)
I20260812 06:18:44.131464  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000018 (ops 84-88)
I20260812 06:18:44.131493  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000019 (ops 89-93)
I20260812 06:18:44.131525  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000020 (ops 94-98)
I20260812 06:18:44.131556  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000021 (ops 99-102)
I20260812 06:18:44.131587  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000022 (ops 103-107)
I20260812 06:18:44.131619  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000023 (ops 108-112)
I20260812 06:18:44.131649  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000024 (ops 113-117)
I20260812 06:18:44.131678  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000025 (ops 118-122)
I20260812 06:18:44.131703  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000026 (ops 123-127)
I20260812 06:18:44.131733  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000027 (ops 128-132)
I20260812 06:18:44.131767  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000028 (ops 133-136)
I20260812 06:18:44.155642  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: LogGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:44.156122  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0): 493 bytes on disk
I20260812 06:18:44.156646  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0) 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:18:44.157126  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:44.169703  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:44.170128  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:44.376776  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.207s	user 0.145s	sys 0.060s Metrics: {"cfile_cache_miss":725,"cfile_cache_miss_bytes":32692484,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":458,"lbm_read_time_us":14196,"lbm_reads_lt_1ms":761,"lbm_write_time_us":33807,"lbm_writes_lt_1ms":734,"mutex_wait_us":57,"peak_mem_usage":86559345,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":3455}
I20260812 06:18:44.377692  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=16.079562
I20260812 06:18:44.438604  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.061s	user 0.045s	sys 0.005s Metrics: {"bytes_written":17804730,"delete_count":0,"lbm_write_time_us":24320,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2170}
I20260812 06:18:44.439128  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=5.165500
I20260812 06:18:44.459583  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":7179480,"delete_count":0,"lbm_write_time_us":7471,"lbm_writes_lt_1ms":178,"reinsert_count":0,"update_count":875}
I20260812 06:18:44.460032  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:44.645936  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.186s	user 0.140s	sys 0.043s Metrics: {"cfile_cache_miss":641,"cfile_cache_miss_bytes":29328297,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":174,"lbm_read_time_us":11390,"lbm_reads_lt_1ms":677,"lbm_write_time_us":30387,"lbm_writes_lt_1ms":652,"peak_mem_usage":75911787,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3045}
I20260812 06:18:44.646976  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=16.079562
I20260812 06:18:44.707141  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.060s	user 0.023s	sys 0.020s Metrics: {"bytes_written":17599605,"delete_count":0,"lbm_write_time_us":18669,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2145}
I20260812 06:18:44.707698  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=5.165500
I20260812 06:18:44.725759  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":7015384,"delete_count":0,"lbm_write_time_us":7112,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:18:44.726182  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:44.922515  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.196s	user 0.132s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959076,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":13324,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34259,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:18:44.923213  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:44.973397  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.050s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21887,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.974130  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:44.998366  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.024s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.998855  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:45.010228  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.010939  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:45.215540  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.204s	user 0.138s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959182,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":307,"lbm_read_time_us":13927,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33542,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":3000}
I20260812 06:18:45.216504  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=16.079562
I20260812 06:18:45.260416  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.044s	user 0.026s	sys 0.012s Metrics: {"bytes_written":17681653,"delete_count":0,"lbm_write_time_us":17146,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:18:45.260979  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:45.271557  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.010s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":2919,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:45.272028  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:45.280851  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3242,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.281348  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:45.467306  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.186s	user 0.123s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959157,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":445,"lbm_read_time_us":12605,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31320,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:18:45.467947  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=14.095187
I20260812 06:18:45.514120  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19990,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.514715  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:45.529603  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.015s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.530150  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushMRSOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:45.572427  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushMRSOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.042s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":150,"dirs.run_wall_time_us":1112,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1933,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:45.573247  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0): 492 bytes on disk
I20260812 06:18:45.573786  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: UndoDeltaBlockGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.574285  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=3.181125
I20260812 06:18:45.586122  5149 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.580s	user 1.666s	sys 0.180s
I20260812 06:18:45.587800  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.013s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3756,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.588193  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling LogGCOp(ec354b36c7cc4325973168684e57cff0): free 129773869 bytes of WAL
I20260812 06:18:45.588400  5604 log_reader.cc:385] T ec354b36c7cc4325973168684e57cff0: removed 13 log segments from log reader
I20260812 06:18:45.588442  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000029 (ops 137-141)
I20260812 06:18:45.588469  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000030 (ops 142-146)
I20260812 06:18:45.588500  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000031 (ops 147-151)
I20260812 06:18:45.588531  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000032 (ops 152-156)
I20260812 06:18:45.588562  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000033 (ops 157-161)
I20260812 06:18:45.588595  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000034 (ops 162-166)
I20260812 06:18:45.588627  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000035 (ops 167-170)
I20260812 06:18:45.588660  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000036 (ops 171-175)
I20260812 06:18:45.588691  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000037 (ops 176-180)
I20260812 06:18:45.588723  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000038 (ops 181-185)
I20260812 06:18:45.588754  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000039 (ops 186-190)
I20260812 06:18:45.588785  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000040 (ops 191-195)
I20260812 06:18:45.588817  5604 log.cc:1079] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: Deleting log segment in path: /tmp/dist-test-task0mnRi0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515515831332-5149-0/minicluster-data/ts-0-root/wals/ec354b36c7cc4325973168684e57cff0/wal-000000041 (ops 196-200)
I20260812 06:18:45.607836  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: LogGCOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.019s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:18:45.608246  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0): perf score=2.188937
I20260812 06:18:45.616848  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: FlushDeltaMemStoresOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3223,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.617274  5709 maintenance_manager.cc:419] P aa45a7c1604741f8a14a24f6a2356963: Scheduling MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0): perf score=1.000000
I20260812 06:18:45.659883  5149 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:18:45.660379  5149 tablet_server.cc:179] TabletServer@127.5.7.65:0 shutting down...
I20260812 06:18:45.769199  5604 maintenance_manager.cc:643] P aa45a7c1604741f8a14a24f6a2356963: MajorDeltaCompactionOp(ec354b36c7cc4325973168684e57cff0) complete. Timing: real 0.152s	user 0.084s	sys 0.064s Metrics: {"cfile_cache_hit":613,"cfile_cache_hit_bytes":25025075,"cfile_cache_miss":121,"cfile_cache_miss_bytes":8036632,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1881,"lbm_read_time_us":4025,"lbm_reads_lt_1ms":153,"lbm_write_time_us":28573,"lbm_writes_lt_1ms":743,"mutex_wait_us":33,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":51456,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:45.769999  5149 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:45.770270  5149 tablet_replica.cc:333] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963: stopping tablet replica
I20260812 06:18:45.770398  5149 raft_consensus.cc:2243] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.770560  5149 raft_consensus.cc:2272] T ec354b36c7cc4325973168684e57cff0 P aa45a7c1604741f8a14a24f6a2356963 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.783700  5149 tablet_server.cc:196] TabletServer@127.5.7.65:0 shutdown complete.
I20260812 06:18:45.824918  5149 master.cc:562] Master@127.5.7.126:34363 shutting down...
I20260812 06:18:45.828193  5149 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.828361  5149 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.828430  5149 tablet_replica.cc:333] T 00000000000000000000000000000000 P d46b0d8e8c0f4a47999906393109a602: stopping tablet replica
I20260812 06:18:45.840536  5149 master.cc:584] Master@127.5.7.126:34363 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5127 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10064 ms total)

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