[==========] 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:19:51.640697  4121 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.6.126:42721
I20260812 06:19:51.641672  4121 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:19:51.642221  4121 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:51.648792  4121 server_base.cc:1061] running on GCE node
W20260812 06:19:51.648850  4130 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:19:51.648993  4131 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:19:51.649103  4134 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:19:51.649688  4121 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.649811  4121 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:19:51.649868  4121 hybrid_clock.cc:648] HybridClock initialized: now 1786515591649865 us; error 0 us; skew 500 ppm
I20260812 06:19:51.651662  4121 webserver.cc:533] Webserver started at http://127.4.6.126:38157/ using document root <none> and password file <none>
I20260812 06:19:51.652220  4121 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.652310  4121 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.652635  4121 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.654289  4121 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/master-0-root/instance:
uuid: "9c5e0bab7fe249dfb9e32db9e661b483"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-10pc"
I20260812 06:19:51.657810  4121 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:51.659925  4140 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:19:51.661078  4121 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:51.661213  4121 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/master-0-root
uuid: "9c5e0bab7fe249dfb9e32db9e661b483"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-10pc"
I20260812 06:19:51.661321  4121 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-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:19:51.677963  4121 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.678642  4121 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:19:51.678838  4121 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.687029  4121 rpc_server.cc:307] RPC server started. Bound to: 127.4.6.126:42721
I20260812 06:19:51.687119  4197 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.6.126:42721 every 8 connection(s)
I20260812 06:19:51.689334  4198 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:19:51.694799  4198 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: Bootstrap starting.
I20260812 06:19:51.697113  4198 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.698028  4198 log.cc:826] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:51.699716  4198 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: No bootstrap required, opened a new log
I20260812 06:19:51.702471  4198 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER }
I20260812 06:19:51.702632  4198 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.702708  4198 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9c5e0bab7fe249dfb9e32db9e661b483, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.703299  4198 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [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: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER }
I20260812 06:19:51.703476  4198 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.703547  4198 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.703712  4198 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.704533  4198 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER }
I20260812 06:19:51.704979  4198 leader_election.cc:304] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [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: 9c5e0bab7fe249dfb9e32db9e661b483; no voters: 
I20260812 06:19:51.705252  4198 leader_election.cc:290] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.705410  4201 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.705668  4201 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 1 LEADER]: Becoming Leader. State: Replica: 9c5e0bab7fe249dfb9e32db9e661b483, State: Running, Role: LEADER
I20260812 06:19:51.706091  4201 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [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: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER }
I20260812 06:19:51.706310  4198 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:51.708164  4202 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER } }
I20260812 06:19:51.708187  4203 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9c5e0bab7fe249dfb9e32db9e661b483. Latest consensus state: current_term: 1 leader_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c5e0bab7fe249dfb9e32db9e661b483" member_type: VOTER } }
I20260812 06:19:51.708316  4202 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.708316  4203 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.708640  4121 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:51.710569  4217 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:51.710633  4217 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:51.710719  4216 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:51.711453  4216 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:51.716300  4216 catalog_manager.cc:1383] Generated new cluster ID: 03bfb891422e4d2b9f0020f8f7313d46
I20260812 06:19:51.716368  4216 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:51.729447  4216 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:51.730715  4216 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:51.737784  4216 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: Generated new TSK 0
I20260812 06:19:51.738559  4216 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:51.741315  4121 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.744233  4222 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:19:51.744288  4223 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:19:51.744472  4121 server_base.cc:1061] running on GCE node
W20260812 06:19:51.744652  4225 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:19:51.744885  4121 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.744966  4121 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:19:51.744992  4121 hybrid_clock.cc:648] HybridClock initialized: now 1786515591744990 us; error 0 us; skew 500 ppm
I20260812 06:19:51.745914  4121 webserver.cc:533] Webserver started at http://127.4.6.65:36213/ using document root <none> and password file <none>
I20260812 06:19:51.746081  4121 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.746138  4121 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.746207  4121 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.746640  4121 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/instance:
uuid: "ae425a4d6ca440849d1ac008dc03a41e"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-10pc"
I20260812 06:19:51.748497  4121 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:51.749719  4231 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:19:51.749991  4121 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:51.750095  4121 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root
uuid: "ae425a4d6ca440849d1ac008dc03a41e"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-10pc"
I20260812 06:19:51.750192  4121 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-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:19:51.754051  4121 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.754451  4121 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.754937  4121 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:51.755748  4121 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:51.755825  4121 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.755897  4121 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:51.755954  4121 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.762847  4121 rpc_server.cc:307] RPC server started. Bound to: 127.4.6.65:33773
I20260812 06:19:51.763079  4303 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.6.65:33773 every 8 connection(s)
I20260812 06:19:51.776997  4304 heartbeater.cc:344] Connected to a master server at 127.4.6.126:42721
I20260812 06:19:51.777258  4304 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:51.777796  4304 heartbeater.cc:507] Master 127.4.6.126:42721 requested a full tablet report, sending...
I20260812 06:19:51.779376  4158 ts_manager.cc:194] Registered new tserver with Master: ae425a4d6ca440849d1ac008dc03a41e (127.4.6.65:33773)
I20260812 06:19:51.779469  4121 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015865368s
I20260812 06:19:51.780959  4158 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42466
I20260812 06:19:51.789472  4158 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42476:
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:19:51.803882  4264 tablet_service.cc:1511] Processing CreateTablet for tablet c75e9ef7bf1c4c43a423253389d3c96d (DEFAULT_TABLE table=heavy-update-compaction-test [id=8de44fc4e01344deb53b5f0eecc24366]), partition=
I20260812 06:19:51.804332  4264 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c75e9ef7bf1c4c43a423253389d3c96d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:51.806568  4318 tablet_bootstrap.cc:492] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Bootstrap starting.
I20260812 06:19:51.807838  4318 tablet_bootstrap.cc:654] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.808977  4318 tablet_bootstrap.cc:492] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: No bootstrap required, opened a new log
I20260812 06:19:51.809106  4318 ts_tablet_manager.cc:1403] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:51.809510  4318 raft_consensus.cc:359] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae425a4d6ca440849d1ac008dc03a41e" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 33773 } }
I20260812 06:19:51.809634  4318 raft_consensus.cc:385] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.809684  4318 raft_consensus.cc:740] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae425a4d6ca440849d1ac008dc03a41e, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.809836  4318 consensus_queue.cc:260] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [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: "ae425a4d6ca440849d1ac008dc03a41e" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 33773 } }
I20260812 06:19:51.809957  4318 raft_consensus.cc:399] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.810007  4318 raft_consensus.cc:493] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.810072  4318 raft_consensus.cc:3060] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.810971  4318 raft_consensus.cc:515] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae425a4d6ca440849d1ac008dc03a41e" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 33773 } }
I20260812 06:19:51.811156  4318 leader_election.cc:304] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [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: ae425a4d6ca440849d1ac008dc03a41e; no voters: 
I20260812 06:19:51.811430  4318 leader_election.cc:290] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.811555  4320 raft_consensus.cc:2804] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.811794  4320 raft_consensus.cc:697] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 1 LEADER]: Becoming Leader. State: Replica: ae425a4d6ca440849d1ac008dc03a41e, State: Running, Role: LEADER
I20260812 06:19:51.811803  4318 ts_tablet_manager.cc:1434] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:51.812005  4304 heartbeater.cc:499] Master 127.4.6.126:42721 was elected leader, sending a full tablet report...
I20260812 06:19:51.812189  4320 consensus_queue.cc:237] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [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: "ae425a4d6ca440849d1ac008dc03a41e" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 33773 } }
I20260812 06:19:51.814927  4158 catalog_manager.cc:5719] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e reported cstate change: term changed from 0 to 1, leader changed from <none> to ae425a4d6ca440849d1ac008dc03a41e (127.4.6.65). New cstate: current_term: 1 leader_uuid: "ae425a4d6ca440849d1ac008dc03a41e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae425a4d6ca440849d1ac008dc03a41e" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 33773 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:51.884861  4121 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.025s	sys 0.002s
I20260812 06:19:52.014389  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=15.086190
I20260812 06:19:52.175668  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.161s	user 0.133s	sys 0.020s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":239,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1037,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38751,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":116,"threads_started":1,"update_count":1450}
I20260812 06:19:52.177050  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d): free 20743880 bytes of WAL
I20260812 06:19:52.177378  4237 log_reader.cc:385] T c75e9ef7bf1c4c43a423253389d3c96d: removed 2 log segments from log reader
I20260812 06:19:52.177469  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000001 (ops 1-6)
I20260812 06:19:52.177520  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000002 (ops 7-11)
I20260812 06:19:52.183543  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:52.183933  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d): 12719216 bytes on disk
I20260812 06:19:52.184631  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.185107  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:52.212527  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.027s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.213004  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:52.225469  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.226131  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:52.395670  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.169s	user 0.147s	sys 0.020s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364569,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":537,"lbm_read_time_us":12929,"lbm_reads_lt_1ms":559,"lbm_write_time_us":28462,"lbm_writes_lt_1ms":533,"mutex_wait_us":24,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":17920,"thread_start_us":349,"threads_started":5,"update_count":2450}
I20260812 06:19:52.396376  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:52.440171  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.043s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18057,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.440742  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:52.453660  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.454154  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:52.572392  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.118s	user 0.085s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1204,"lbm_read_time_us":9020,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21290,"lbm_writes_lt_1ms":443,"mutex_wait_us":512,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:19:52.573071  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:52.612339  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.039s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.612898  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:52.624806  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.625327  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:52.752898  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.127s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":8000,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26330,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.753618  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:52.802273  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16252,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.802829  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:52.814507  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.814970  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:52.955652  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.140s	user 0.084s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":11416,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21882,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:52.956180  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:53.002497  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.046s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14604,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.003034  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.018769  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.019392  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:53.159839  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.140s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1169,"lbm_read_time_us":9966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27108,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:19:53.160576  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:53.198203  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.037s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15596,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.198716  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.209771  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.210551  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:53.338698  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":921,"lbm_read_time_us":8493,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25828,"lbm_writes_lt_1ms":443,"mutex_wait_us":209,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:53.339475  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=10.126437
I20260812 06:19:53.384649  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.045s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17407,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.385151  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.398123  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4431,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.398825  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:53.426481  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":141,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1440,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1557,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:53.427400  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d): free 112239261 bytes of WAL
I20260812 06:19:53.427649  4237 log_reader.cc:385] T c75e9ef7bf1c4c43a423253389d3c96d: removed 11 log segments from log reader
I20260812 06:19:53.427699  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000003 (ops 12-16)
I20260812 06:19:53.427752  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000004 (ops 17-21)
I20260812 06:19:53.427796  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000005 (ops 22-26)
I20260812 06:19:53.427858  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000006 (ops 27-31)
I20260812 06:19:53.427897  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000007 (ops 32-36)
I20260812 06:19:53.427934  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000008 (ops 37-41)
I20260812 06:19:53.427973  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000009 (ops 42-46)
I20260812 06:19:53.428009  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000010 (ops 47-51)
I20260812 06:19:53.428046  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000011 (ops 52-56)
I20260812 06:19:53.428084  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000012 (ops 57-60)
I20260812 06:19:53.428124  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000013 (ops 61-65)
I20260812 06:19:53.454214  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:53.454686  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=3.181125
I20260812 06:19:53.474057  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7011,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.474499  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d): 448 bytes on disk
I20260812 06:19:53.474886  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.475327  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.485075  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.485502  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:53.673022  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.187s	user 0.143s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1077,"lbm_read_time_us":14056,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35074,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:19:53.673730  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:53.723758  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21383,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.724216  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.740722  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.741235  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:53.889220  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.148s	user 0.103s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":10248,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29701,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:53.889804  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:53.939566  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.050s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22647,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.940016  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:53.952296  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.952775  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:54.122375  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.169s	user 0.113s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":9636,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32170,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:19:54.123162  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:54.189159  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.066s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23105,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.189630  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:54.200758  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.201534  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:54.380050  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.178s	user 0.106s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":415,"lbm_read_time_us":14158,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29787,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2500}
I20260812 06:19:54.380898  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:54.430114  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.049s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.430639  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:54.443894  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.444322  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:54.611833  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.167s	user 0.119s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":12908,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28660,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:19:54.612623  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:54.667059  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.054s	user 0.030s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20629,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.667729  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:54.678503  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.678990  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:54.855567  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.176s	user 0.126s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":13378,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30624,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:54.856127  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=11.118625
I20260812 06:19:54.889412  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13431,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.889936  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:54.928865  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.039s	user 0.015s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5484,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.929584  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:54.940800  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.941301  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:54.990147  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.049s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2345,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":1280}
I20260812 06:19:54.990877  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d): free 128867497 bytes of WAL
I20260812 06:19:54.991123  4237 log_reader.cc:385] T c75e9ef7bf1c4c43a423253389d3c96d: removed 13 log segments from log reader
I20260812 06:19:54.991171  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000014 (ops 66-70)
I20260812 06:19:54.991201  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000015 (ops 71-74)
I20260812 06:19:54.991259  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000016 (ops 75-79)
I20260812 06:19:54.991302  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000017 (ops 80-84)
I20260812 06:19:54.991321  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000018 (ops 85-89)
I20260812 06:19:54.991359  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000019 (ops 90-94)
I20260812 06:19:54.991400  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000020 (ops 95-98)
I20260812 06:19:54.991427  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000021 (ops 99-103)
I20260812 06:19:54.991477  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000022 (ops 104-108)
I20260812 06:19:54.991516  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000023 (ops 109-112)
I20260812 06:19:54.991559  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000024 (ops 113-117)
I20260812 06:19:54.991600  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000025 (ops 118-122)
I20260812 06:19:54.991636  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000026 (ops 123-127)
I20260812 06:19:55.020905  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:55.021387  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d): 492 bytes on disk
I20260812 06:19:55.021955  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: UndoDeltaBlockGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.022642  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=3.181125
I20260812 06:19:55.036787  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4667,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:55.037307  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:55.048265  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.048961  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:55.309617  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.260s	user 0.156s	sys 0.093s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1327,"lbm_read_time_us":16703,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37846,"lbm_writes_lt_1ms":743,"mutex_wait_us":919,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:19:55.310497  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=18.063937
I20260812 06:19:55.378599  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.068s	user 0.031s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24221,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.379160  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:55.394950  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.016s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.395694  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:55.597200  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.201s	user 0.138s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":13348,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34872,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":3000}
I20260812 06:19:55.597936  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:55.643870  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.046s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20735,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.644444  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:55.810207  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.165s	user 0.116s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":309,"lbm_read_time_us":10673,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27567,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:19:55.811088  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:55.860005  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21956,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.860565  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:55.873256  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.873837  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:56.064090  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.190s	user 0.118s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":13432,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29025,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:56.064867  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:56.116046  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.051s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21511,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.116772  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:56.134166  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.134696  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:56.294196  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.159s	user 0.119s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":9090,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28378,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:19:56.295023  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:56.345568  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.050s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20033,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.346081  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:56.357652  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.358119  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:56.519817  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.162s	user 0.134s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1096,"lbm_read_time_us":11768,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31147,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:56.520620  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=14.095187
I20260812 06:19:56.572345  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.052s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22685,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.572921  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:56.584734  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.585474  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:56.617986  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushMRSOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1404,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1996,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:56.618739  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d): free 137634860 bytes of WAL
I20260812 06:19:56.619009  4237 log_reader.cc:385] T c75e9ef7bf1c4c43a423253389d3c96d: removed 14 log segments from log reader
I20260812 06:19:56.619073  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000027 (ops 128-132)
I20260812 06:19:56.619112  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000028 (ops 133-136)
I20260812 06:19:56.619155  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000029 (ops 137-141)
I20260812 06:19:56.619179  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000030 (ops 142-146)
I20260812 06:19:56.619202  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000031 (ops 147-151)
I20260812 06:19:56.619232  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000032 (ops 152-156)
I20260812 06:19:56.619258  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000033 (ops 157-160)
I20260812 06:19:56.619290  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000034 (ops 161-165)
I20260812 06:19:56.619318  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000035 (ops 166-170)
I20260812 06:19:56.619345  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000036 (ops 171-175)
I20260812 06:19:56.619366  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000037 (ops 176-180)
I20260812 06:19:56.619397  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000038 (ops 181-184)
I20260812 06:19:56.619431  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000039 (ops 185-189)
I20260812 06:19:56.619458  4237 log.cc:1079] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/c75e9ef7bf1c4c43a423253389d3c96d/wal-000000040 (ops 190-194)
I20260812 06:19:56.650930  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: LogGCOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:56.651404  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=3.181125
I20260812 06:19:56.664744  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5153,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.665307  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=2.188937
I20260812 06:19:56.675917  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: FlushDeltaMemStoresOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3787,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.676594  4306 maintenance_manager.cc:419] P ae425a4d6ca440849d1ac008dc03a41e: Scheduling MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d): perf score=1.000000
I20260812 06:19:56.772938  4121 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.888s	user 1.803s	sys 0.137s
I20260812 06:19:56.877425  4121 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.104s	user 0.002s	sys 0.000s
I20260812 06:19:56.878075  4121 tablet_server.cc:179] TabletServer@127.4.6.65:0 shutting down...
I20260812 06:19:56.899240  4237 maintenance_manager.cc:643] P ae425a4d6ca440849d1ac008dc03a41e: MajorDeltaCompactionOp(c75e9ef7bf1c4c43a423253389d3c96d) complete. Timing: real 0.222s	user 0.136s	sys 0.081s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2935,"lbm_read_time_us":14390,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35611,"lbm_writes_lt_1ms":743,"mutex_wait_us":57,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:19:56.899865  4121 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:56.900710  4121 tablet_replica.cc:333] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e: stopping tablet replica
I20260812 06:19:56.900978  4121 raft_consensus.cc:2243] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.901217  4121 raft_consensus.cc:2272] T c75e9ef7bf1c4c43a423253389d3c96d P ae425a4d6ca440849d1ac008dc03a41e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.917845  4121 tablet_server.cc:196] TabletServer@127.4.6.65:0 shutdown complete.
I20260812 06:19:56.954890  4121 master.cc:562] Master@127.4.6.126:42721 shutting down...
I20260812 06:19:56.959004  4121 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.959211  4121 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.959298  4121 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9c5e0bab7fe249dfb9e32db9e661b483: stopping tablet replica
I20260812 06:19:56.971750  4121 master.cc:584] Master@127.4.6.126:42721 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5417 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:57.071677  4121 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.6.126:33841
I20260812 06:19:57.072132  4121 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:57.074393  4343 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:19:57.074426  4345 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:19:57.074591  4341 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:19:57.074700  4121 server_base.cc:1061] running on GCE node
I20260812 06:19:57.074838  4121 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:57.074883  4121 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:19:57.074899  4121 hybrid_clock.cc:648] HybridClock initialized: now 1786515597074900 us; error 0 us; skew 500 ppm
I20260812 06:19:57.075733  4121 webserver.cc:533] Webserver started at http://127.4.6.126:39049/ using document root <none> and password file <none>
I20260812 06:19:57.075901  4121 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:57.075970  4121 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:57.076097  4121 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:57.076555  4121 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/master-0-root/instance:
uuid: "1357f666dd7444c5a79ce5f8917715d4"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-10pc"
I20260812 06:19:57.078243  4121 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:57.079085  4350 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:19:57.079299  4121 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:57.079396  4121 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/master-0-root
uuid: "1357f666dd7444c5a79ce5f8917715d4"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-10pc"
I20260812 06:19:57.079470  4121 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-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:19:57.087292  4121 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:57.087628  4121 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:57.091688  4121 rpc_server.cc:307] RPC server started. Bound to: 127.4.6.126:33841
I20260812 06:19:57.092350  4409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.6.126:33841 every 8 connection(s)
I20260812 06:19:57.093605  4410 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:19:57.098578  4410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4: Bootstrap starting.
I20260812 06:19:57.099498  4410 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:57.100559  4410 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4: No bootstrap required, opened a new log
I20260812 06:19:57.100956  4410 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER }
I20260812 06:19:57.101078  4410 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:57.101130  4410 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1357f666dd7444c5a79ce5f8917715d4, State: Initialized, Role: FOLLOWER
I20260812 06:19:57.101305  4410 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [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: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER }
I20260812 06:19:57.101373  4410 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:57.101426  4410 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:57.101485  4410 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:57.102159  4410 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER }
I20260812 06:19:57.102299  4410 leader_election.cc:304] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [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: 1357f666dd7444c5a79ce5f8917715d4; no voters: 
I20260812 06:19:57.102514  4410 leader_election.cc:290] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:57.102635  4413 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:57.102869  4413 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 1 LEADER]: Becoming Leader. State: Replica: 1357f666dd7444c5a79ce5f8917715d4, State: Running, Role: LEADER
I20260812 06:19:57.102960  4410 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:57.103036  4413 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [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: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER }
I20260812 06:19:57.103470  4415 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1357f666dd7444c5a79ce5f8917715d4. Latest consensus state: current_term: 1 leader_uuid: "1357f666dd7444c5a79ce5f8917715d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER } }
I20260812 06:19:57.103569  4415 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:57.103456  4414 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1357f666dd7444c5a79ce5f8917715d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1357f666dd7444c5a79ce5f8917715d4" member_type: VOTER } }
I20260812 06:19:57.103783  4414 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:57.103838  4419 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:57.104753  4419 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:57.105031  4121 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:57.106637  4419 catalog_manager.cc:1383] Generated new cluster ID: 21d12a2cd4574f2eab0bab2f8be474b5
I20260812 06:19:57.106695  4419 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:57.114863  4419 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:57.115382  4419 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:57.123375  4419 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4: Generated new TSK 0
I20260812 06:19:57.123544  4419 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:57.137543  4121 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:57.139724  4434 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:19:57.139712  4438 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:19:57.139686  4436 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:19:57.139747  4121 server_base.cc:1061] running on GCE node
I20260812 06:19:57.140002  4121 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:57.140053  4121 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:19:57.140070  4121 hybrid_clock.cc:648] HybridClock initialized: now 1786515597140070 us; error 0 us; skew 500 ppm
I20260812 06:19:57.140933  4121 webserver.cc:533] Webserver started at http://127.4.6.65:46673/ using document root <none> and password file <none>
I20260812 06:19:57.141075  4121 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:57.141122  4121 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:57.141183  4121 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:57.141557  4121 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/instance:
uuid: "487fe53ec78b4f7083c0d12f3c6550ff"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-10pc"
I20260812 06:19:57.143013  4121 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:57.143872  4443 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:19:57.144119  4121 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:57.144204  4121 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root
uuid: "487fe53ec78b4f7083c0d12f3c6550ff"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-10pc"
I20260812 06:19:57.144284  4121 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-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:19:57.151193  4121 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:57.151558  4121 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:57.151846  4121 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:57.152290  4121 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:57.152346  4121 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.152402  4121 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:57.152447  4121 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.157020  4121 rpc_server.cc:307] RPC server started. Bound to: 127.4.6.65:44591
I20260812 06:19:57.157044  4520 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.6.65:44591 every 8 connection(s)
I20260812 06:19:57.166599  4521 heartbeater.cc:344] Connected to a master server at 127.4.6.126:33841
I20260812 06:19:57.166724  4521 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:57.166915  4521 heartbeater.cc:507] Master 127.4.6.126:33841 requested a full tablet report, sending...
I20260812 06:19:57.167523  4369 ts_manager.cc:194] Registered new tserver with Master: 487fe53ec78b4f7083c0d12f3c6550ff (127.4.6.65:44591)
I20260812 06:19:57.168226  4369 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36306
I20260812 06:19:57.168521  4121 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011074884s
I20260812 06:19:57.175254  4369 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36312:
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:19:57.184530  4476 tablet_service.cc:1511] Processing CreateTablet for tablet 728687a6a3a44ba3b5705c45808ac1fe (DEFAULT_TABLE table=heavy-update-compaction-test [id=bb450a9bd0a44ce182ac8578df28c315]), partition=
I20260812 06:19:57.184825  4476 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 728687a6a3a44ba3b5705c45808ac1fe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:57.186880  4535 tablet_bootstrap.cc:492] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Bootstrap starting.
I20260812 06:19:57.187810  4535 tablet_bootstrap.cc:654] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:57.188850  4535 tablet_bootstrap.cc:492] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: No bootstrap required, opened a new log
I20260812 06:19:57.188925  4535 ts_tablet_manager.cc:1403] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:57.189399  4535 raft_consensus.cc:359] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "487fe53ec78b4f7083c0d12f3c6550ff" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 44591 } }
I20260812 06:19:57.189519  4535 raft_consensus.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:57.189558  4535 raft_consensus.cc:740] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 487fe53ec78b4f7083c0d12f3c6550ff, State: Initialized, Role: FOLLOWER
I20260812 06:19:57.189725  4535 consensus_queue.cc:260] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [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: "487fe53ec78b4f7083c0d12f3c6550ff" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 44591 } }
I20260812 06:19:57.189841  4535 raft_consensus.cc:399] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:57.189932  4535 raft_consensus.cc:493] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:57.190007  4535 raft_consensus.cc:3060] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:57.190734  4535 raft_consensus.cc:515] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "487fe53ec78b4f7083c0d12f3c6550ff" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 44591 } }
I20260812 06:19:57.190848  4535 leader_election.cc:304] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [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: 487fe53ec78b4f7083c0d12f3c6550ff; no voters: 
I20260812 06:19:57.191009  4535 leader_election.cc:290] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:57.191143  4538 raft_consensus.cc:2804] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:57.191404  4521 heartbeater.cc:499] Master 127.4.6.126:33841 was elected leader, sending a full tablet report...
I20260812 06:19:57.191394  4535 ts_tablet_manager.cc:1434] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:57.191391  4538 raft_consensus.cc:697] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 1 LEADER]: Becoming Leader. State: Replica: 487fe53ec78b4f7083c0d12f3c6550ff, State: Running, Role: LEADER
I20260812 06:19:57.191636  4538 consensus_queue.cc:237] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [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: "487fe53ec78b4f7083c0d12f3c6550ff" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 44591 } }
I20260812 06:19:57.192909  4369 catalog_manager.cc:5719] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff reported cstate change: term changed from 0 to 1, leader changed from <none> to 487fe53ec78b4f7083c0d12f3c6550ff (127.4.6.65). New cstate: current_term: 1 leader_uuid: "487fe53ec78b4f7083c0d12f3c6550ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "487fe53ec78b4f7083c0d12f3c6550ff" member_type: VOTER last_known_addr { host: "127.4.6.65" port: 44591 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:57.253763  4121 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:19:57.407884  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=19.054940
I20260812 06:19:57.571214  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.163s	user 0.120s	sys 0.039s Metrics: {"bytes_written":13784359,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":855,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42639,"lbm_writes_lt_1ms":803,"mutex_wait_us":179,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1792,"update_count":1680}
I20260812 06:19:57.571918  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling LogGCOp(728687a6a3a44ba3b5705c45808ac1fe): free 20743880 bytes of WAL
I20260812 06:19:57.572202  4449 log_reader.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe: removed 2 log segments from log reader
I20260812 06:19:57.572268  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000001 (ops 1-6)
I20260812 06:19:57.572314  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000002 (ops 7-11)
I20260812 06:19:57.578346  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: LogGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:57.578760  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:57.593777  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":5976,"lbm_writes_lt_1ms":106,"mutex_wait_us":125,"reinsert_count":0,"update_count":515}
I20260812 06:19:57.594190  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:57.600327  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2070,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:19:57.600739  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:57.786849  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.186s	user 0.115s	sys 0.065s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405517,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":673,"lbm_read_time_us":11984,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29083,"lbm_writes_lt_1ms":533,"mutex_wait_us":22,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":333,"threads_started":5,"update_count":2450}
I20260812 06:19:57.787516  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe): 16821652 bytes on disk
I20260812 06:19:57.788030  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.788421  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:19:57.835845  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.047s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.836323  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:57.990370  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.154s	user 0.084s	sys 0.065s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":753,"lbm_read_time_us":10830,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22765,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:57.990911  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:19:58.046532  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.055s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21426,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.047037  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.057705  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.058180  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:58.262894  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.205s	user 0.149s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":687,"lbm_read_time_us":12651,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29359,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:58.268785  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:19:58.325867  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.057s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24653,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.326370  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.346659  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.020s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.347143  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:58.511164  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.164s	user 0.131s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":403,"lbm_read_time_us":10443,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30380,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:58.511859  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:19:58.564654  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.053s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.565209  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.580798  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.581452  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:58.733311  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.152s	user 0.101s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1013,"lbm_read_time_us":10011,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33273,"lbm_writes_lt_1ms":543,"mutex_wait_us":447,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:58.734097  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=11.118625
I20260812 06:19:58.768136  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.034s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14051,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:58.768797  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.791849  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.023s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4945,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.792327  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.802479  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.802912  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:58.833050  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":35,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1432,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1628,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:58.833597  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling LogGCOp(728687a6a3a44ba3b5705c45808ac1fe): free 112239323 bytes of WAL
I20260812 06:19:58.833801  4449 log_reader.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe: removed 11 log segments from log reader
I20260812 06:19:58.833842  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000003 (ops 12-16)
I20260812 06:19:58.833870  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000004 (ops 17-21)
I20260812 06:19:58.833930  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000005 (ops 22-26)
I20260812 06:19:58.833969  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000006 (ops 27-31)
I20260812 06:19:58.834021  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000007 (ops 32-36)
I20260812 06:19:58.834060  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000008 (ops 37-41)
I20260812 06:19:58.834097  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000009 (ops 42-46)
I20260812 06:19:58.834133  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000010 (ops 47-50)
I20260812 06:19:58.834170  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000011 (ops 51-55)
I20260812 06:19:58.834208  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000012 (ops 56-60)
I20260812 06:19:58.834247  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000013 (ops 61-65)
I20260812 06:19:58.859756  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: LogGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:58.860234  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe): 446 bytes on disk
I20260812 06:19:58.860723  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.861191  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=3.181125
I20260812 06:19:58.873193  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:58.873626  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling LogGCOp(728687a6a3a44ba3b5705c45808ac1fe): free 12017932 bytes of WAL
I20260812 06:19:58.873827  4449 log_reader.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe: removed 1 log segments from log reader
I20260812 06:19:58.873874  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000014 (ops 66-70)
I20260812 06:19:58.876216  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: LogGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:58.876572  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:58.888753  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.899744  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:59.131276  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.231s	user 0.136s	sys 0.095s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":625,"lbm_read_time_us":17292,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38273,"lbm_writes_lt_1ms":743,"mutex_wait_us":60,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:59.131942  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=18.063937
I20260812 06:19:59.210717  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.079s	user 0.034s	sys 0.043s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29330,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:59.211262  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:59.225971  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.226552  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:59.434553  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.208s	user 0.131s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":12100,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34843,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:59.435302  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=16.079562
I20260812 06:19:59.490935  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.055s	user 0.033s	sys 0.016s Metrics: {"bytes_written":18091891,"delete_count":0,"lbm_write_time_us":23369,"lbm_writes_lt_1ms":444,"reinsert_count":0,"update_count":2205}
I20260812 06:19:59.491402  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.196750
I20260812 06:19:59.501780  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2830884,"delete_count":0,"lbm_write_time_us":2799,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:59.502179  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:59.511929  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3803,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:59.512354  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:19:59.720821  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.208s	user 0.121s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":217,"lbm_read_time_us":14914,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32207,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":3000}
I20260812 06:19:59.721410  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=18.063937
I20260812 06:19:59.795652  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.074s	user 0.029s	sys 0.029s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28683,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.796128  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:19:59.807610  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.808084  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:00.014384  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.206s	user 0.135s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":15497,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34342,"lbm_writes_lt_1ms":643,"mutex_wait_us":303,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":3000}
I20260812 06:20:00.015061  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:20:00.063463  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.064225  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.088862  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":500}
I20260812 06:20:00.089345  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.100770  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.101420  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:00.317114  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.215s	user 0.142s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":183,"lbm_read_time_us":14711,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34231,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:20:00.317876  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=16.079562
I20260812 06:20:00.368397  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.050s	user 0.037s	sys 0.009s Metrics: {"bytes_written":17804725,"delete_count":0,"lbm_write_time_us":22005,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:20:00.369227  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.196750
I20260812 06:20:00.391721  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.022s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:20:00.392206  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.402618  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3992,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.403088  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:00.438023  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.035s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1671,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:00.438766  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling LogGCOp(728687a6a3a44ba3b5705c45808ac1fe): free 129320534 bytes of WAL
I20260812 06:20:00.439055  4449 log_reader.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe: removed 13 log segments from log reader
I20260812 06:20:00.439133  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000015 (ops 71-75)
I20260812 06:20:00.439173  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000016 (ops 76-80)
I20260812 06:20:00.439201  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000017 (ops 81-85)
I20260812 06:20:00.439230  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000018 (ops 86-90)
I20260812 06:20:00.439260  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000019 (ops 91-94)
I20260812 06:20:00.439291  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000020 (ops 95-99)
I20260812 06:20:00.439323  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000021 (ops 100-104)
I20260812 06:20:00.439347  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000022 (ops 105-109)
I20260812 06:20:00.439376  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000023 (ops 110-114)
I20260812 06:20:00.439404  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000024 (ops 115-118)
I20260812 06:20:00.439431  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000025 (ops 119-123)
I20260812 06:20:00.439466  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000026 (ops 124-128)
I20260812 06:20:00.439498  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000027 (ops 129-133)
I20260812 06:20:00.470089  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: LogGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:00.470533  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=3.181125
I20260812 06:20:00.483462  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4713,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:00.483923  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.494082  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.494622  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe): 492 bytes on disk
I20260812 06:20:00.495047  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.495551  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:00.747149  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.251s	user 0.180s	sys 0.067s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123234,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2310,"lbm_read_time_us":18879,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45221,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:20:00.747905  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=18.063937
I20260812 06:20:00.808919  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.060s	user 0.037s	sys 0.022s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27291,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:00.809520  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.837427  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.028s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.837944  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:00.848874  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.849375  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.036998  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.187s	user 0.147s	sys 0.039s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020628,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":89,"lbm_read_time_us":14516,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37400,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3500}
I20260812 06:20:01.037669  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:20:01.084826  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.047s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.085605  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:01.105638  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.020s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.106069  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.258430  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.152s	user 0.099s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1199,"lbm_read_time_us":8882,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28959,"lbm_writes_lt_1ms":543,"mutex_wait_us":419,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:20:01.259076  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=14.095187
I20260812 06:20:01.311076  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.052s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23583,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.311654  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.468150  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.156s	user 0.085s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":237,"lbm_read_time_us":10680,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26193,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:20:01.469014  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=11.118625
I20260812 06:20:01.502116  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.033s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14535,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.502835  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:01.523448  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.019s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5147,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.524082  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.654300  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.130s	user 0.086s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1775,"lbm_read_time_us":9054,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24377,"lbm_writes_lt_1ms":443,"mutex_wait_us":861,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:20:01.654942  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=10.126437
I20260812 06:20:01.686826  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.032s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13231,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.687311  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:01.697875  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.698329  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.823146  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.125s	user 0.101s	sys 0.023s 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":530,"lbm_read_time_us":8997,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23463,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2000}
I20260812 06:20:01.823652  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=10.126437
I20260812 06:20:01.870810  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.047s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15701,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.871289  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=2.188937
I20260812 06:20:01.883167  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.883970  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:01.916667  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushMRSOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.032s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1378,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1786,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":2816}
I20260812 06:20:01.917378  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling LogGCOp(728687a6a3a44ba3b5705c45808ac1fe): free 121006697 bytes of WAL
I20260812 06:20:01.917608  4449 log_reader.cc:385] T 728687a6a3a44ba3b5705c45808ac1fe: removed 12 log segments from log reader
I20260812 06:20:01.917654  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000028 (ops 134-138)
I20260812 06:20:01.917682  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000029 (ops 139-142)
I20260812 06:20:01.917742  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000030 (ops 143-147)
I20260812 06:20:01.917770  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000031 (ops 148-152)
I20260812 06:20:01.917810  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000032 (ops 153-157)
I20260812 06:20:01.917851  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000033 (ops 158-162)
I20260812 06:20:01.917894  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000034 (ops 163-167)
I20260812 06:20:01.917935  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000035 (ops 168-172)
I20260812 06:20:01.917975  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000036 (ops 173-177)
I20260812 06:20:01.918015  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000037 (ops 178-182)
I20260812 06:20:01.918056  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000038 (ops 183-187)
I20260812 06:20:01.918095  4449 log.cc:1079] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: Deleting log segment in path: /tmp/dist-test-taskHiJR6P/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515591630127-4121-0/minicluster-data/ts-0-root/wals/728687a6a3a44ba3b5705c45808ac1fe/wal-000000039 (ops 188-192)
I20260812 06:20:01.946424  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: LogGCOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:01.946938  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=3.181125
I20260812 06:20:01.960647  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5586,"lbm_writes_lt_1ms":131,"mutex_wait_us":72,"reinsert_count":0,"update_count":640}
I20260812 06:20:01.961102  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.196750
I20260812 06:20:01.971582  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3270,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:01.972012  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=1.000000
I20260812 06:20:02.108202  4121 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.854s	user 1.813s	sys 0.131s
I20260812 06:20:02.150318  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: MajorDeltaCompactionOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.178s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918307,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13772,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37319,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:02.150797  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe): 473 bytes on disk
I20260812 06:20:02.151192  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: UndoDeltaBlockGCOp(728687a6a3a44ba3b5705c45808ac1fe) 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:20:02.151723  4522 maintenance_manager.cc:419] P 487fe53ec78b4f7083c0d12f3c6550ff: Scheduling FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe): perf score=10.126437
I20260812 06:20:02.171963  4121 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.001s	sys 0.000s
I20260812 06:20:02.172534  4121 tablet_server.cc:179] TabletServer@127.4.6.65:0 shutting down...
I20260812 06:20:02.184722  4449 maintenance_manager.cc:643] P 487fe53ec78b4f7083c0d12f3c6550ff: FlushDeltaMemStoresOp(728687a6a3a44ba3b5705c45808ac1fe) complete. Timing: real 0.033s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14103,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.185542  4121 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:02.185767  4121 tablet_replica.cc:333] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff: stopping tablet replica
I20260812 06:20:02.185945  4121 raft_consensus.cc:2243] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.186142  4121 raft_consensus.cc:2272] T 728687a6a3a44ba3b5705c45808ac1fe P 487fe53ec78b4f7083c0d12f3c6550ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.200220  4121 tablet_server.cc:196] TabletServer@127.4.6.65:0 shutdown complete.
I20260812 06:20:02.211396  4121 master.cc:562] Master@127.4.6.126:33841 shutting down...
I20260812 06:20:02.215152  4121 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.215338  4121 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.215397  4121 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1357f666dd7444c5a79ce5f8917715d4: stopping tablet replica
I20260812 06:20:02.227898  4121 master.cc:584] Master@127.4.6.126:33841 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5262 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10680 ms total)

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