[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:02.973224  3228 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.39.62:39333
I20260812 06:18:02.974329  3228 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:02.975029  3228 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:02.981683  3235 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.981773  3228 server_base.cc:1061] running on GCE node
W20260812 06:18:02.981684  3233 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:02.981976  3237 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:02.982561  3228 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:02.982693  3228 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:02.982759  3228 hybrid_clock.cc:648] HybridClock initialized: now 1786515482982756 us; error 0 us; skew 500 ppm
I20260812 06:18:02.984701  3228 webserver.cc:533] Webserver started at http://127.3.39.62:33141/ using document root <none> and password file <none>
I20260812 06:18:02.985306  3228 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:02.985404  3228 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:02.985692  3228 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:02.987380  3228 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/master-0-root/instance:
uuid: "a1122b9513b140c093768ff4453788ee"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1jjb"
I20260812 06:18:02.991312  3228 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.006s	sys 0.000s
I20260812 06:18:02.993489  3243 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:02.994438  3228 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:02.994585  3228 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/master-0-root
uuid: "a1122b9513b140c093768ff4453788ee"
format_stamp: "Formatted at 2026-08-12 06:18:02 on dist-test-slave-1jjb"
I20260812 06:18:02.994693  3228 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.019428  3228 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.020175  3228 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:03.020376  3228 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.027957  3228 rpc_server.cc:307] RPC server started. Bound to: 127.3.39.62:39333
I20260812 06:18:03.028018  3297 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.39.62:39333 every 8 connection(s)
I20260812 06:18:03.030336  3298 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.035766  3298 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: Bootstrap starting.
I20260812 06:18:03.038126  3298 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.039011  3298 log.cc:826] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:03.040741  3298 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: No bootstrap required, opened a new log
I20260812 06:18:03.043488  3298 raft_consensus.cc:359] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1122b9513b140c093768ff4453788ee" member_type: VOTER }
I20260812 06:18:03.043653  3298 raft_consensus.cc:385] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.043694  3298 raft_consensus.cc:740] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a1122b9513b140c093768ff4453788ee, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.044286  3298 consensus_queue.cc:260] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [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: "a1122b9513b140c093768ff4453788ee" member_type: VOTER }
I20260812 06:18:03.044425  3298 raft_consensus.cc:399] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.044466  3298 raft_consensus.cc:493] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.044555  3298 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.045336  3298 raft_consensus.cc:515] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1122b9513b140c093768ff4453788ee" member_type: VOTER }
I20260812 06:18:03.045723  3298 leader_election.cc:304] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [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: a1122b9513b140c093768ff4453788ee; no voters: 
I20260812 06:18:03.046011  3298 leader_election.cc:290] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.046164  3303 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.046432  3303 raft_consensus.cc:697] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 1 LEADER]: Becoming Leader. State: Replica: a1122b9513b140c093768ff4453788ee, State: Running, Role: LEADER
I20260812 06:18:03.046892  3303 consensus_queue.cc:237] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [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: "a1122b9513b140c093768ff4453788ee" member_type: VOTER }
I20260812 06:18:03.047111  3298 sys_catalog.cc:565] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.048897  3304 sys_catalog.cc:455] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a1122b9513b140c093768ff4453788ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1122b9513b140c093768ff4453788ee" member_type: VOTER } }
I20260812 06:18:03.048938  3305 sys_catalog.cc:455] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader a1122b9513b140c093768ff4453788ee. Latest consensus state: current_term: 1 leader_uuid: "a1122b9513b140c093768ff4453788ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a1122b9513b140c093768ff4453788ee" member_type: VOTER } }
I20260812 06:18:03.049033  3304 sys_catalog.cc:458] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.049045  3305 sys_catalog.cc:458] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.049422  3314 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.049610  3228 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.051900  3314 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.056680  3314 catalog_manager.cc:1383] Generated new cluster ID: 61809952f1044c1391ae58c057e9fd6f
I20260812 06:18:03.056751  3314 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.085098  3314 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.086053  3314 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.097898  3314 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: Generated new TSK 0
I20260812 06:18:03.098853  3314 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:03.114598  3228 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.118173  3325 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.118331  3228 server_base.cc:1061] running on GCE node
W20260812 06:18:03.118223  3328 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.118253  3326 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.118702  3228 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.118745  3228 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.118762  3228 hybrid_clock.cc:648] HybridClock initialized: now 1786515483118761 us; error 0 us; skew 500 ppm
I20260812 06:18:03.119693  3228 webserver.cc:533] Webserver started at http://127.3.39.1:36497/ using document root <none> and password file <none>
I20260812 06:18:03.119887  3228 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.119939  3228 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.120048  3228 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.120464  3228 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/instance:
uuid: "3ee552c7099b417caf0cf33d2ad001c8"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-1jjb"
I20260812 06:18:03.122200  3228 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:03.123234  3333 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.123478  3228 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:03.123569  3228 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root
uuid: "3ee552c7099b417caf0cf33d2ad001c8"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-1jjb"
I20260812 06:18:03.123660  3228 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.130016  3228 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.130455  3228 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.130921  3228 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:03.131834  3228 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:03.131906  3228 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.131994  3228 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:03.132035  3228 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.138932  3228 rpc_server.cc:307] RPC server started. Bound to: 127.3.39.1:39285
I20260812 06:18:03.138957  3404 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.39.1:39285 every 8 connection(s)
I20260812 06:18:03.154311  3405 heartbeater.cc:344] Connected to a master server at 127.3.39.62:39333
I20260812 06:18:03.154592  3405 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:03.155097  3405 heartbeater.cc:507] Master 127.3.39.62:39333 requested a full tablet report, sending...
I20260812 06:18:03.156747  3261 ts_manager.cc:194] Registered new tserver with Master: 3ee552c7099b417caf0cf33d2ad001c8 (127.3.39.1:39285)
I20260812 06:18:03.157661  3228 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01799258s
I20260812 06:18:03.158121  3261 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36740
I20260812 06:18:03.167788  3261 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36746:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:03.182509  3366 tablet_service.cc:1511] Processing CreateTablet for tablet 0b42e4d621274a50ae1c4b2e1c56ecd9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=48adbb066972459b84e383508ce72859]), partition=
I20260812 06:18:03.183034  3366 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0b42e4d621274a50ae1c4b2e1c56ecd9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.185942  3419 tablet_bootstrap.cc:492] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Bootstrap starting.
I20260812 06:18:03.187268  3419 tablet_bootstrap.cc:654] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.188838  3419 tablet_bootstrap.cc:492] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: No bootstrap required, opened a new log
I20260812 06:18:03.189018  3419 ts_tablet_manager.cc:1403] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:03.189872  3419 raft_consensus.cc:359] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ee552c7099b417caf0cf33d2ad001c8" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 39285 } }
I20260812 06:18:03.190018  3419 raft_consensus.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.190070  3419 raft_consensus.cc:740] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3ee552c7099b417caf0cf33d2ad001c8, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.190237  3419 consensus_queue.cc:260] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [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: "3ee552c7099b417caf0cf33d2ad001c8" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 39285 } }
I20260812 06:18:03.190367  3419 raft_consensus.cc:399] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.190428  3419 raft_consensus.cc:493] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.190482  3419 raft_consensus.cc:3060] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.191839  3419 raft_consensus.cc:515] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ee552c7099b417caf0cf33d2ad001c8" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 39285 } }
I20260812 06:18:03.192109  3419 leader_election.cc:304] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [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: 3ee552c7099b417caf0cf33d2ad001c8; no voters: 
I20260812 06:18:03.192378  3419 leader_election.cc:290] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.192782  3419 ts_tablet_manager.cc:1434] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:03.193030  3422 raft_consensus.cc:2804] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.193032  3405 heartbeater.cc:499] Master 127.3.39.62:39333 was elected leader, sending a full tablet report...
I20260812 06:18:03.193279  3422 raft_consensus.cc:697] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 1 LEADER]: Becoming Leader. State: Replica: 3ee552c7099b417caf0cf33d2ad001c8, State: Running, Role: LEADER
I20260812 06:18:03.193454  3422 consensus_queue.cc:237] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [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: "3ee552c7099b417caf0cf33d2ad001c8" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 39285 } }
I20260812 06:18:03.197125  3261 catalog_manager.cc:5719] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3ee552c7099b417caf0cf33d2ad001c8 (127.3.39.1). New cstate: current_term: 1 leader_uuid: "3ee552c7099b417caf0cf33d2ad001c8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ee552c7099b417caf0cf33d2ad001c8" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 39285 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:03.276957  3228 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.071s	user 0.022s	sys 0.012s
I20260812 06:18:03.390276  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=15.086190
I20260812 06:18:03.562233  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.172s	user 0.129s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":232,"delete_count":0,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":828,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43738,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":1280,"thread_start_us":139,"threads_started":1,"update_count":1500}
I20260812 06:18:03.563472  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): free 8725963 bytes of WAL
I20260812 06:18:03.563895  3339 log_reader.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9: removed 1 log segments from log reader
I20260812 06:18:03.564016  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000001 (ops 1-6)
I20260812 06:18:03.566689  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:03.567014  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:03.581957  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5413,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.582564  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:03.713435  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.131s	user 0.106s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":10177,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23287,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":281,"threads_started":5,"update_count":2000}
I20260812 06:18:03.713905  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): 12308958 bytes on disk
I20260812 06:18:03.714351  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.714774  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:03.763625  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.049s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.764285  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:03.781023  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6140,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.781675  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:03.905471  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.123s	user 0.083s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":8859,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25513,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.906047  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:03.945188  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.039s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.945672  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:03.960639  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.015s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.961241  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.087031  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.126s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":693,"lbm_read_time_us":10362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23038,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:18:04.087790  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:04.137907  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.050s	user 0.026s	sys 0.022s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17539,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.138638  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.150085  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.150600  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.308123  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.157s	user 0.101s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":11976,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26473,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:18:04.308871  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:04.350594  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.042s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17210,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.351138  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.363098  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.363598  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.496356  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.133s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":609,"lbm_read_time_us":9967,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26674,"lbm_writes_lt_1ms":443,"mutex_wait_us":89,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:18:04.497128  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:04.544750  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.047s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19373,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:18:04.545243  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.556921  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.557487  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.679941  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.122s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":906,"lbm_read_time_us":9380,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24040,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:18:04.680544  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:04.721364  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.041s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17861,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.721819  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.735592  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.736150  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.761759  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.025s	user 0.019s	sys 0.005s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":130,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1677,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:04.762776  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): free 120553370 bytes of WAL
I20260812 06:18:04.763013  3339 log_reader.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9: removed 12 log segments from log reader
I20260812 06:18:04.763063  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000002 (ops 7-11)
I20260812 06:18:04.763101  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000003 (ops 12-16)
I20260812 06:18:04.763137  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000004 (ops 17-21)
I20260812 06:18:04.763161  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000005 (ops 22-26)
I20260812 06:18:04.763183  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000006 (ops 27-30)
I20260812 06:18:04.763212  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000007 (ops 31-35)
I20260812 06:18:04.763242  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000008 (ops 36-40)
I20260812 06:18:04.763274  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000009 (ops 41-44)
I20260812 06:18:04.763309  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000010 (ops 45-49)
I20260812 06:18:04.763337  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000011 (ops 50-54)
I20260812 06:18:04.763366  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000012 (ops 55-59)
I20260812 06:18:04.763397  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000013 (ops 60-64)
I20260812 06:18:04.792954  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:04.793581  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): 447 bytes on disk
I20260812 06:18:04.794165  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.794685  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.808645  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.809078  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:04.820042  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.820725  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:04.989706  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.169s	user 0.151s	sys 0.018s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":225,"lbm_read_time_us":12320,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36226,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:04.990480  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:05.053442  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.062s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22506,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.054162  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:05.208204  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.154s	user 0.122s	sys 0.020s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":301,"dirs.run_cpu_time_us":2817,"dirs.run_wall_time_us":15508,"lbm_read_time_us":9528,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26683,"lbm_writes_lt_1ms":443,"mutex_wait_us":6642,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:05.208815  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:05.264722  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.053s	user 0.028s	sys 0.022s Metrics: {"bytes_written":13456168,"delete_count":0,"lbm_write_time_us":18761,"lbm_writes_lt_1ms":331,"mutex_wait_us":180,"reinsert_count":0,"update_count":1640}
I20260812 06:18:05.265287  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:05.276657  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102663,"delete_count":0,"lbm_write_time_us":4443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.277099  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.196750
I20260812 06:18:05.285514  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3153,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:05.285930  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:05.459811  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.174s	user 0.139s	sys 0.034s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733821,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":217,"lbm_read_time_us":13694,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33593,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:05.460655  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=11.118625
I20260812 06:18:05.508397  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.048s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16524,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:05.508950  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:05.524950  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.525427  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:05.682219  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.157s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":970,"lbm_read_time_us":9662,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23955,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:18:05.682902  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:05.732821  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.050s	user 0.022s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.733340  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:05.744735  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.745222  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:05.904420  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.159s	user 0.139s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":70,"lbm_read_time_us":9864,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34503,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:05.905119  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:05.936153  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.031s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14059,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.936650  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:05.949352  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.950273  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:06.079808  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.129s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":11487,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24277,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":90752,"update_count":2000}
I20260812 06:18:06.080556  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=10.126437
I20260812 06:18:06.124693  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.044s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.125260  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:06.136420  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.137177  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:06.166695  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1299,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1620,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:06.167419  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): free 120100341 bytes of WAL
I20260812 06:18:06.167662  3339 log_reader.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9: removed 12 log segments from log reader
I20260812 06:18:06.167709  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000014 (ops 65-68)
I20260812 06:18:06.167762  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000015 (ops 69-73)
I20260812 06:18:06.167809  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000016 (ops 74-78)
I20260812 06:18:06.167851  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000017 (ops 79-83)
I20260812 06:18:06.167893  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000018 (ops 84-88)
I20260812 06:18:06.167953  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000019 (ops 89-93)
I20260812 06:18:06.167992  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000020 (ops 94-98)
I20260812 06:18:06.168035  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000021 (ops 99-102)
I20260812 06:18:06.168102  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000022 (ops 103-107)
I20260812 06:18:06.168144  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000023 (ops 108-112)
I20260812 06:18:06.168184  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000024 (ops 113-116)
I20260812 06:18:06.168224  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000025 (ops 117-121)
I20260812 06:18:06.198717  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:06.199270  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=3.181125
I20260812 06:18:06.216930  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":5210313,"delete_count":0,"lbm_write_time_us":7321,"lbm_writes_lt_1ms":130,"reinsert_count":0,"update_count":635}
I20260812 06:18:06.217377  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.196750
I20260812 06:18:06.227025  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":3224,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:18:06.227566  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:06.401964  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.174s	user 0.102s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":183,"lbm_read_time_us":13079,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36032,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:06.402522  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:06.457677  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.055s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24406,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.458277  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:06.474915  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.475373  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:06.631377  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.156s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":962,"lbm_read_time_us":9797,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29417,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:18:06.632092  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:06.700714  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.068s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25518,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.701227  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): 447 bytes on disk
I20260812 06:18:06.701649  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.702173  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:06.712687  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.713387  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:06.904361  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.191s	user 0.094s	sys 0.090s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":13737,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31895,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:18:06.905054  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:06.965430  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.060s	user 0.018s	sys 0.041s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.965961  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:06.978034  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.978660  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:07.178881  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.200s	user 0.130s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":456,"lbm_read_time_us":11713,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32573,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:07.184686  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=11.118625
I20260812 06:18:07.262877  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.078s	user 0.043s	sys 0.031s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":25973,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:18:07.263783  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=5.165500
I20260812 06:18:07.293332  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.029s	user 0.016s	sys 0.011s Metrics: {"bytes_written":6933335,"delete_count":0,"lbm_write_time_us":11730,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:18:07.294070  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:07.531502  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.237s	user 0.177s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733733,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1198,"lbm_read_time_us":19779,"lbm_reads_lt_1ms":564,"lbm_write_time_us":42806,"lbm_writes_lt_1ms":543,"mutex_wait_us":410,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:07.532522  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=19.056125
I20260812 06:18:07.596983  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.064s	user 0.019s	sys 0.044s Metrics: {"bytes_written":20922553,"delete_count":0,"lbm_write_time_us":25033,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:18:07.597596  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:07.622052  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.024s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.622541  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:07.632477  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.010s	user 0.004s	sys 0.005s 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:18:07.632952  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:07.668542  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushMRSOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.035s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193506,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1282,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1405,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:07.669380  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): free 112239536 bytes of WAL
I20260812 06:18:07.669637  3339 log_reader.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9: removed 11 log segments from log reader
I20260812 06:18:07.669706  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000026 (ops 122-126)
I20260812 06:18:07.669761  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000027 (ops 127-131)
I20260812 06:18:07.669818  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000028 (ops 132-136)
I20260812 06:18:07.669860  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000029 (ops 137-141)
I20260812 06:18:07.669896  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000030 (ops 142-146)
I20260812 06:18:07.669930  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000031 (ops 147-150)
I20260812 06:18:07.669963  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000032 (ops 151-155)
I20260812 06:18:07.670003  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000033 (ops 156-160)
I20260812 06:18:07.670039  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000034 (ops 161-165)
I20260812 06:18:07.670075  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000035 (ops 166-170)
I20260812 06:18:07.670112  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000036 (ops 171-175)
I20260812 06:18:07.695979  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.026s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:18:07.696555  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): 463 bytes on disk
I20260812 06:18:07.697036  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: UndoDeltaBlockGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.697723  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=3.181125
I20260812 06:18:07.711012  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:07.711472  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9): free 12017954 bytes of WAL
I20260812 06:18:07.711685  3339 log_reader.cc:385] T 0b42e4d621274a50ae1c4b2e1c56ecd9: removed 1 log segments from log reader
I20260812 06:18:07.711731  3339 log.cc:1079] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/0b42e4d621274a50ae1c4b2e1c56ecd9/wal-000000037 (ops 176-180)
I20260812 06:18:07.714236  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: LogGCOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:07.714570  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:07.725246  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.725765  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:07.997560  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.272s	user 0.187s	sys 0.084s Metrics: {"cfile_cache_miss":935,"cfile_cache_miss_bytes":41143703,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1042,"lbm_read_time_us":20999,"lbm_reads_lt_1ms":975,"lbm_write_time_us":51005,"lbm_writes_lt_1ms":943,"mutex_wait_us":313,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":8960,"thread_start_us":77,"threads_started":1,"update_count":4500}
I20260812 06:18:07.998538  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=18.063937
I20260812 06:18:08.059948  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.061s	user 0.033s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28070,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:08.060755  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=2.188937
I20260812 06:18:08.079641  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.019s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.080173  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:08.217100  3228 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.939s	user 1.803s	sys 0.118s
I20260812 06:18:08.238716  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.158s	user 0.111s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12340,"lbm_reads_lt_1ms":660,"lbm_write_time_us":31282,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:08.239283  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=14.095187
I20260812 06:18:08.280754  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: FlushDeltaMemStoresOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.041s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.281294  3406 maintenance_manager.cc:419] P 3ee552c7099b417caf0cf33d2ad001c8: Scheduling MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9): perf score=1.000000
I20260812 06:18:08.288589  3228 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.005s	sys 0.000s
I20260812 06:18:08.290495  3228 tablet_server.cc:179] TabletServer@127.3.39.1:0 shutting down...
I20260812 06:18:08.405112  3339 maintenance_manager.cc:643] P 3ee552c7099b417caf0cf33d2ad001c8: MajorDeltaCompactionOp(0b42e4d621274a50ae1c4b2e1c56ecd9) complete. Timing: real 0.124s	user 0.101s	sys 0.020s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1271,"lbm_read_time_us":10289,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27311,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":434,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:18:08.405792  3228 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:08.406273  3228 tablet_replica.cc:333] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8: stopping tablet replica
I20260812 06:18:08.406565  3228 raft_consensus.cc:2243] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.406834  3228 raft_consensus.cc:2272] T 0b42e4d621274a50ae1c4b2e1c56ecd9 P 3ee552c7099b417caf0cf33d2ad001c8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.422628  3228 tablet_server.cc:196] TabletServer@127.3.39.1:0 shutdown complete.
I20260812 06:18:08.446905  3228 master.cc:562] Master@127.3.39.62:39333 shutting down...
I20260812 06:18:08.451092  3228 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.451275  3228 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.451329  3228 tablet_replica.cc:333] T 00000000000000000000000000000000 P a1122b9513b140c093768ff4453788ee: stopping tablet replica
I20260812 06:18:08.464967  3228 master.cc:584] Master@127.3.39.62:39333 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5590 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:08.576594  3228 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.39.62:34671
I20260812 06:18:08.577056  3228 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.579433  3440 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.579476  3443 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.579447  3228 server_base.cc:1061] running on GCE node
W20260812 06:18:08.579455  3439 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.579864  3228 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.579905  3228 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:08.579924  3228 hybrid_clock.cc:648] HybridClock initialized: now 1786515488579925 us; error 0 us; skew 500 ppm
I20260812 06:18:08.580758  3228 webserver.cc:533] Webserver started at http://127.3.39.62:39915/ using document root <none> and password file <none>
I20260812 06:18:08.580894  3228 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.580936  3228 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.580998  3228 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.581357  3228 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/master-0-root/instance:
uuid: "b84c431469464e258b293156a86876fe"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1jjb"
I20260812 06:18:08.582855  3228 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:08.583704  3448 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.583928  3228 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:08.583992  3228 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/master-0-root
uuid: "b84c431469464e258b293156a86876fe"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1jjb"
I20260812 06:18:08.584116  3228 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:08.605053  3228 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.605540  3228 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.610405  3228 rpc_server.cc:307] RPC server started. Bound to: 127.3.39.62:34671
I20260812 06:18:08.616595  3511 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.39.62:34671 every 8 connection(s)
I20260812 06:18:08.617084  3512 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.618932  3512 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe: Bootstrap starting.
I20260812 06:18:08.619692  3512 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.620806  3512 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe: No bootstrap required, opened a new log
I20260812 06:18:08.621168  3512 raft_consensus.cc:359] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b84c431469464e258b293156a86876fe" member_type: VOTER }
I20260812 06:18:08.621253  3512 raft_consensus.cc:385] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.621274  3512 raft_consensus.cc:740] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b84c431469464e258b293156a86876fe, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.621424  3512 consensus_queue.cc:260] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [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: "b84c431469464e258b293156a86876fe" member_type: VOTER }
I20260812 06:18:08.621528  3512 raft_consensus.cc:399] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.621554  3512 raft_consensus.cc:493] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.621587  3512 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.622239  3512 raft_consensus.cc:515] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b84c431469464e258b293156a86876fe" member_type: VOTER }
I20260812 06:18:08.622355  3512 leader_election.cc:304] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [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: b84c431469464e258b293156a86876fe; no voters: 
I20260812 06:18:08.622535  3512 leader_election.cc:290] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.622707  3515 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.622905  3515 raft_consensus.cc:697] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 1 LEADER]: Becoming Leader. State: Replica: b84c431469464e258b293156a86876fe, State: Running, Role: LEADER
I20260812 06:18:08.623091  3512 sys_catalog.cc:565] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:08.623067  3515 consensus_queue.cc:237] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [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: "b84c431469464e258b293156a86876fe" member_type: VOTER }
I20260812 06:18:08.623528  3518 sys_catalog.cc:455] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [sys.catalog]: SysCatalogTable state changed. Reason: New leader b84c431469464e258b293156a86876fe. Latest consensus state: current_term: 1 leader_uuid: "b84c431469464e258b293156a86876fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b84c431469464e258b293156a86876fe" member_type: VOTER } }
I20260812 06:18:08.623637  3518 sys_catalog.cc:458] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.623871  3516 sys_catalog.cc:455] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b84c431469464e258b293156a86876fe" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b84c431469464e258b293156a86876fe" member_type: VOTER } }
I20260812 06:18:08.623932  3520 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:08.624250  3516 sys_catalog.cc:458] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.624928  3520 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:08.625207  3228 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:08.626686  3520 catalog_manager.cc:1383] Generated new cluster ID: 32e6ae31bded44e9bd9fbb68d30ef14d
I20260812 06:18:08.626744  3520 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:08.637923  3520 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:08.638509  3520 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:08.643468  3520 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe: Generated new TSK 0
I20260812 06:18:08.643633  3520 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:08.657487  3228 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.659502  3536 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.659615  3540 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.659639  3537 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.659771  3228 server_base.cc:1061] running on GCE node
I20260812 06:18:08.660008  3228 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.660058  3228 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:08.660117  3228 hybrid_clock.cc:648] HybridClock initialized: now 1786515488660117 us; error 0 us; skew 500 ppm
I20260812 06:18:08.661002  3228 webserver.cc:533] Webserver started at http://127.3.39.1:39801/ using document root <none> and password file <none>
I20260812 06:18:08.661134  3228 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.661180  3228 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.661230  3228 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.661579  3228 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/instance:
uuid: "33a654e46de74dbda7ea8f566e73d077"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1jjb"
I20260812 06:18:08.662997  3228 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:08.663906  3545 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.664197  3228 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:08.664290  3228 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root
uuid: "33a654e46de74dbda7ea8f566e73d077"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-1jjb"
I20260812 06:18:08.664377  3228 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:08.676491  3228 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.676834  3228 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.677135  3228 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:08.677589  3228 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:08.677649  3228 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.677709  3228 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:08.677742  3228 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.682266  3228 rpc_server.cc:307] RPC server started. Bound to: 127.3.39.1:34721
I20260812 06:18:08.682915  3615 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.39.1:34721 every 8 connection(s)
I20260812 06:18:08.690973  3616 heartbeater.cc:344] Connected to a master server at 127.3.39.62:34671
I20260812 06:18:08.691074  3616 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:08.691267  3616 heartbeater.cc:507] Master 127.3.39.62:34671 requested a full tablet report, sending...
I20260812 06:18:08.691918  3467 ts_manager.cc:194] Registered new tserver with Master: 33a654e46de74dbda7ea8f566e73d077 (127.3.39.1:34721)
I20260812 06:18:08.692625  3467 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53136
I20260812 06:18:08.692997  3228 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009951932s
I20260812 06:18:08.699936  3467 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53138:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:08.708652  3572 tablet_service.cc:1511] Processing CreateTablet for tablet dbfe765c80144fa58621e091f65556dc (DEFAULT_TABLE table=heavy-update-compaction-test [id=385ce05f13be415aab94284e3c2c931f]), partition=
I20260812 06:18:08.708889  3572 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dbfe765c80144fa58621e091f65556dc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.710752  3628 tablet_bootstrap.cc:492] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Bootstrap starting.
I20260812 06:18:08.711658  3628 tablet_bootstrap.cc:654] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.712698  3628 tablet_bootstrap.cc:492] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: No bootstrap required, opened a new log
I20260812 06:18:08.712770  3628 ts_tablet_manager.cc:1403] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:18:08.713115  3628 raft_consensus.cc:359] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33a654e46de74dbda7ea8f566e73d077" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 34721 } }
I20260812 06:18:08.713202  3628 raft_consensus.cc:385] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.713224  3628 raft_consensus.cc:740] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 33a654e46de74dbda7ea8f566e73d077, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.713358  3628 consensus_queue.cc:260] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [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: "33a654e46de74dbda7ea8f566e73d077" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 34721 } }
I20260812 06:18:08.713443  3628 raft_consensus.cc:399] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.713474  3628 raft_consensus.cc:493] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.713510  3628 raft_consensus.cc:3060] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.714259  3628 raft_consensus.cc:515] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33a654e46de74dbda7ea8f566e73d077" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 34721 } }
I20260812 06:18:08.714423  3628 leader_election.cc:304] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [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: 33a654e46de74dbda7ea8f566e73d077; no voters: 
I20260812 06:18:08.714584  3628 leader_election.cc:290] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.714715  3630 raft_consensus.cc:2804] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.714906  3628 ts_tablet_manager.cc:1434] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:08.714918  3616 heartbeater.cc:499] Master 127.3.39.62:34671 was elected leader, sending a full tablet report...
I20260812 06:18:08.714964  3630 raft_consensus.cc:697] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 1 LEADER]: Becoming Leader. State: Replica: 33a654e46de74dbda7ea8f566e73d077, State: Running, Role: LEADER
I20260812 06:18:08.715159  3630 consensus_queue.cc:237] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [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: "33a654e46de74dbda7ea8f566e73d077" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 34721 } }
I20260812 06:18:08.716552  3467 catalog_manager.cc:5719] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 reported cstate change: term changed from 0 to 1, leader changed from <none> to 33a654e46de74dbda7ea8f566e73d077 (127.3.39.1). New cstate: current_term: 1 leader_uuid: "33a654e46de74dbda7ea8f566e73d077" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33a654e46de74dbda7ea8f566e73d077" member_type: VOTER last_known_addr { host: "127.3.39.1" port: 34721 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:08.778079  3228 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.014s	sys 0.008s
I20260812 06:18:08.933619  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushMRSOp(dbfe765c80144fa58621e091f65556dc): perf score=19.054940
I20260812 06:18:09.093518  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushMRSOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.160s	user 0.095s	sys 0.063s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":743,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38613,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:09.094489  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling LogGCOp(dbfe765c80144fa58621e091f65556dc): free 20743880 bytes of WAL
I20260812 06:18:09.094787  3550 log_reader.cc:385] T dbfe765c80144fa58621e091f65556dc: removed 2 log segments from log reader
I20260812 06:18:09.094851  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000001 (ops 1-6)
I20260812 06:18:09.094904  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000002 (ops 7-11)
I20260812 06:18:09.100282  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: LogGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:09.100656  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:09.128388  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.028s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.128914  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc): 16411400 bytes on disk
I20260812 06:18:09.129423  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.129884  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:09.144701  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.145270  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:09.335949  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.190s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":653,"lbm_read_time_us":14364,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31046,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":359,"threads_started":5,"update_count":2500}
I20260812 06:18:09.336725  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:09.405912  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.069s	user 0.033s	sys 0.034s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24494,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.406607  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:09.424935  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.425488  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:09.633364  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.208s	user 0.124s	sys 0.072s 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":1075,"lbm_read_time_us":14987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34439,"lbm_writes_lt_1ms":543,"mutex_wait_us":293,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:09.634024  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:09.701359  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.067s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.701972  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:09.718777  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.719445  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:09.923452  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.204s	user 0.133s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":14756,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32681,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:09.924052  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:09.982600  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.058s	user 0.046s	sys 0.005s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24187,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.983050  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:10.005221  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.005757  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:10.198401  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.192s	user 0.121s	sys 0.067s 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":186,"lbm_read_time_us":15729,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28908,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33024,"update_count":2500}
I20260812 06:18:10.199512  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:10.255883  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.056s	user 0.026s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22499,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.256433  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:10.272605  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.275163  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:10.470901  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.195s	user 0.125s	sys 0.064s 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":160,"lbm_read_time_us":12269,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34356,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2500}
I20260812 06:18:10.471587  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:10.533233  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.061s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":29659,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.533792  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:10.546749  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.547216  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushMRSOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:10.576506  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushMRSOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1389,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1962,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:10.577157  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling LogGCOp(dbfe765c80144fa58621e091f65556dc): free 121006430 bytes of WAL
I20260812 06:18:10.577456  3550 log_reader.cc:385] T dbfe765c80144fa58621e091f65556dc: removed 12 log segments from log reader
I20260812 06:18:10.577521  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000003 (ops 12-16)
I20260812 06:18:10.577562  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000004 (ops 17-21)
I20260812 06:18:10.577590  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000005 (ops 22-26)
I20260812 06:18:10.577612  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000006 (ops 27-30)
I20260812 06:18:10.577641  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000007 (ops 31-35)
I20260812 06:18:10.577663  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000008 (ops 36-40)
I20260812 06:18:10.577694  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000009 (ops 41-45)
I20260812 06:18:10.577720  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000010 (ops 46-50)
I20260812 06:18:10.577754  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000011 (ops 51-55)
I20260812 06:18:10.577783  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000012 (ops 56-60)
I20260812 06:18:10.577809  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000013 (ops 61-65)
I20260812 06:18:10.577834  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000014 (ops 66-70)
I20260812 06:18:10.610173  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: LogGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:10.610754  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=3.181125
I20260812 06:18:10.632851  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.022s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4457,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:10.633318  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:10.643357  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.644227  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:10.906162  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.262s	user 0.141s	sys 0.112s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1150,"lbm_read_time_us":16762,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45041,"lbm_writes_lt_1ms":743,"mutex_wait_us":35,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:18:10.906996  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc): 473 bytes on disk
I20260812 06:18:10.907634  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.908458  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=18.063937
I20260812 06:18:10.979691  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.071s	user 0.035s	sys 0.029s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30551,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:10.980226  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:10.992048  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.992678  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:11.192873  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.200s	user 0.131s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":13686,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35097,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":3000}
I20260812 06:18:11.201155  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=15.087375
I20260812 06:18:11.251405  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.050s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16697072,"delete_count":0,"lbm_write_time_us":22043,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2035}
I20260812 06:18:11.251943  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:11.269338  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5456,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:11.269909  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:11.441579  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.171s	user 0.131s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":12301,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28418,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:18:11.442268  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:11.496671  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.054s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24410,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.497265  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:11.510098  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4605,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.510607  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:11.703779  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.193s	user 0.109s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1020,"lbm_read_time_us":15177,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32806,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:18:11.704586  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:11.767076  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.062s	user 0.037s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.767748  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:11.778532  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.779008  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:11.989938  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.211s	user 0.141s	sys 0.063s 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":150,"lbm_read_time_us":14625,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35080,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2500}
I20260812 06:18:11.990564  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:12.043829  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.053s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18483,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.044445  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:12.067860  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.023s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.068509  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushMRSOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:12.100838  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushMRSOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":311,"dirs.run_wall_time_us":1588,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1578,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:12.101574  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling LogGCOp(dbfe765c80144fa58621e091f65556dc): free 115490132 bytes of WAL
I20260812 06:18:12.101819  3550 log_reader.cc:385] T dbfe765c80144fa58621e091f65556dc: removed 11 log segments from log reader
I20260812 06:18:12.101866  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000015 (ops 71-74)
I20260812 06:18:12.101894  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000016 (ops 75-79)
I20260812 06:18:12.101958  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000017 (ops 80-84)
I20260812 06:18:12.102008  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000018 (ops 85-89)
I20260812 06:18:12.102051  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000019 (ops 90-94)
I20260812 06:18:12.102101  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000020 (ops 95-99)
I20260812 06:18:12.102135  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000021 (ops 100-104)
I20260812 06:18:12.102176  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000022 (ops 105-109)
I20260812 06:18:12.102214  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000023 (ops 110-114)
I20260812 06:18:12.102252  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000024 (ops 115-119)
I20260812 06:18:12.102290  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000025 (ops 120-124)
I20260812 06:18:12.128362  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: LogGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:12.128767  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=3.181125
I20260812 06:18:12.147323  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.018s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4508,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:12.147850  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:12.158914  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4186,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.159497  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:12.409889  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.250s	user 0.140s	sys 0.110s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":321,"lbm_read_time_us":18065,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41361,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":22144,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:18:12.410563  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc): 447 bytes on disk
I20260812 06:18:12.411134  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.411893  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=18.063937
I20260812 06:18:12.475260  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.063s	user 0.030s	sys 0.026s Metrics: {"bytes_written":20512342,"delete_count":0,"lbm_write_time_us":27202,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:12.475721  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:12.487289  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.487850  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:12.698691  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.211s	user 0.136s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877130,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":14126,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35933,"lbm_writes_lt_1ms":643,"mutex_wait_us":16,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":3000}
I20260812 06:18:12.699497  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=16.079562
I20260812 06:18:12.759593  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.060s	user 0.032s	sys 0.019s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":24586,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:18:12.760061  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:12.770601  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.010s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3200109,"delete_count":0,"lbm_write_time_us":3194,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:12.771025  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:12.780426  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3654,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.780839  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:12.993774  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.213s	user 0.132s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":682,"lbm_read_time_us":14496,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35245,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:12.994418  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=16.079562
I20260812 06:18:13.066614  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.072s	user 0.040s	sys 0.015s Metrics: {"bytes_written":18173939,"delete_count":0,"lbm_write_time_us":27170,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":444,"reinsert_count":0,"update_count":2215}
I20260812 06:18:13.067107  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=5.165500
I20260812 06:18:13.084196  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6441048,"delete_count":0,"lbm_write_time_us":6982,"lbm_writes_lt_1ms":160,"reinsert_count":0,"update_count":785}
I20260812 06:18:13.084646  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:13.308692  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.224s	user 0.146s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":15140,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34751,"lbm_writes_lt_1ms":643,"mutex_wait_us":360,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":3000}
I20260812 06:18:13.309469  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=18.063937
I20260812 06:18:13.365087  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.055s	user 0.032s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25310,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:13.365552  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:13.531997  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.166s	user 0.133s	sys 0.033s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":221,"lbm_read_time_us":12054,"lbm_reads_lt_1ms":563,"lbm_write_time_us":28328,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:13.532789  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=14.095187
I20260812 06:18:13.585421  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.052s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18092,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:13.585994  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:13.597316  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.597777  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushMRSOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:13.643792  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushMRSOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.046s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1317,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1481,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:13.644618  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling LogGCOp(dbfe765c80144fa58621e091f65556dc): free 121006688 bytes of WAL
I20260812 06:18:13.644884  3550 log_reader.cc:385] T dbfe765c80144fa58621e091f65556dc: removed 12 log segments from log reader
I20260812 06:18:13.644954  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000026 (ops 125-129)
I20260812 06:18:13.645013  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000027 (ops 130-134)
I20260812 06:18:13.645057  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000028 (ops 135-139)
I20260812 06:18:13.645100  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000029 (ops 140-144)
I20260812 06:18:13.645143  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000030 (ops 145-149)
I20260812 06:18:13.645185  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000031 (ops 150-154)
I20260812 06:18:13.645226  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000032 (ops 155-159)
I20260812 06:18:13.645268  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000033 (ops 160-164)
I20260812 06:18:13.645306  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000034 (ops 165-168)
I20260812 06:18:13.645339  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000035 (ops 169-173)
I20260812 06:18:13.645383  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000036 (ops 174-178)
I20260812 06:18:13.645426  3550 log.cc:1079] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: Deleting log segment in path: /tmp/dist-test-taskYxzs7H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515482961529-3228-0/minicluster-data/ts-0-root/wals/dbfe765c80144fa58621e091f65556dc/wal-000000037 (ops 179-183)
I20260812 06:18:13.674017  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: LogGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:13.674540  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=3.181125
I20260812 06:18:13.689463  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4348804,"delete_count":0,"lbm_write_time_us":4746,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:13.689999  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:13.700374  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.010s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:13.700884  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:13.932379  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.231s	user 0.161s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979747,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":377,"lbm_read_time_us":16274,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42747,"lbm_writes_lt_1ms":743,"mutex_wait_us":69,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":69248,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:13.933352  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc): 473 bytes on disk
I20260812 06:18:13.933807  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: UndoDeltaBlockGCOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.934747  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=18.063937
I20260812 06:18:13.987672  3228 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.209s	user 1.943s	sys 0.230s
I20260812 06:18:13.989943  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.055s	user 0.033s	sys 0.022s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26513,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:13.990446  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc): perf score=2.188937
I20260812 06:18:14.005852  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: FlushDeltaMemStoresOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.006446  3617 maintenance_manager.cc:419] P 33a654e46de74dbda7ea8f566e73d077: Scheduling MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc): perf score=1.000000
I20260812 06:18:14.025578  3228 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.037s	user 0.002s	sys 0.000s
I20260812 06:18:14.026094  3228 tablet_server.cc:179] TabletServer@127.3.39.1:0 shutting down...
I20260812 06:18:14.157255  3550 maintenance_manager.cc:643] P 33a654e46de74dbda7ea8f566e73d077: MajorDeltaCompactionOp(dbfe765c80144fa58621e091f65556dc) complete. Timing: real 0.151s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614715,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":555,"lbm_read_time_us":11232,"lbm_reads_lt_1ms":618,"lbm_write_time_us":27827,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":3000}
I20260812 06:18:14.158253  3228 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:14.158564  3228 tablet_replica.cc:333] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077: stopping tablet replica
I20260812 06:18:14.158710  3228 raft_consensus.cc:2243] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.158901  3228 raft_consensus.cc:2272] T dbfe765c80144fa58621e091f65556dc P 33a654e46de74dbda7ea8f566e73d077 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.162999  3228 tablet_server.cc:196] TabletServer@127.3.39.1:0 shutdown complete.
I20260812 06:18:14.210251  3228 master.cc:562] Master@127.3.39.62:34671 shutting down...
I20260812 06:18:14.214509  3228 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.214716  3228 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.214797  3228 tablet_replica.cc:333] T 00000000000000000000000000000000 P b84c431469464e258b293156a86876fe: stopping tablet replica
I20260812 06:18:14.227195  3228 master.cc:584] Master@127.3.39.62:34671 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5760 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11352 ms total)

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