[==========] 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:16:59.359310  2403 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.88.254:42269
I20260812 06:16:59.360513  2403 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:16:59.361225  2403 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:59.368831  2413 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:16:59.368846  2410 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:16:59.369107  2409 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:16:59.369349  2403 server_base.cc:1061] running on GCE node
I20260812 06:16:59.370108  2403 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:59.370221  2403 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:16:59.370260  2403 hybrid_clock.cc:648] HybridClock initialized: now 1786515419370257 us; error 0 us; skew 500 ppm
I20260812 06:16:59.372370  2403 webserver.cc:533] Webserver started at http://127.2.88.254:33415/ using document root <none> and password file <none>
I20260812 06:16:59.373217  2403 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:59.373309  2403 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:59.373543  2403 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:59.375576  2403 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/master-0-root/instance:
uuid: "de75341c7b3744f58d95dda11feca969"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-g350"
I20260812 06:16:59.380693  2403 fs_manager.cc:696] Time spent creating directory manager: real 0.005s	user 0.005s	sys 0.000s
I20260812 06:16:59.384284  2419 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:16:59.385744  2403 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:59.385923  2403 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/master-0-root
uuid: "de75341c7b3744f58d95dda11feca969"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-g350"
I20260812 06:16:59.386067  2403 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-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:16:59.400513  2403 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.401278  2403 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:16:59.401497  2403 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.410406  2403 rpc_server.cc:307] RPC server started. Bound to: 127.2.88.254:42269
I20260812 06:16:59.410416  2477 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.88.254:42269 every 8 connection(s)
I20260812 06:16:59.412963  2478 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:16:59.419457  2478 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: Bootstrap starting.
I20260812 06:16:59.422132  2478 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.423235  2478 log.cc:826] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:59.425326  2478 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: No bootstrap required, opened a new log
I20260812 06:16:59.428547  2478 raft_consensus.cc:359] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de75341c7b3744f58d95dda11feca969" member_type: VOTER }
I20260812 06:16:59.428776  2478 raft_consensus.cc:385] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.428822  2478 raft_consensus.cc:740] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: de75341c7b3744f58d95dda11feca969, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.429579  2478 consensus_queue.cc:260] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [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: "de75341c7b3744f58d95dda11feca969" member_type: VOTER }
I20260812 06:16:59.429790  2478 raft_consensus.cc:399] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.429890  2478 raft_consensus.cc:493] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.430047  2478 raft_consensus.cc:3060] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.430989  2478 raft_consensus.cc:515] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de75341c7b3744f58d95dda11feca969" member_type: VOTER }
I20260812 06:16:59.431519  2478 leader_election.cc:304] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [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: de75341c7b3744f58d95dda11feca969; no voters: 
I20260812 06:16:59.431900  2478 leader_election.cc:290] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.432390  2482 raft_consensus.cc:2804] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.432991  2482 raft_consensus.cc:697] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 1 LEADER]: Becoming Leader. State: Replica: de75341c7b3744f58d95dda11feca969, State: Running, Role: LEADER
I20260812 06:16:59.433167  2478 sys_catalog.cc:565] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:59.433693  2482 consensus_queue.cc:237] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [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: "de75341c7b3744f58d95dda11feca969" member_type: VOTER }
I20260812 06:16:59.435948  2403 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:59.436321  2485 sys_catalog.cc:455] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [sys.catalog]: SysCatalogTable state changed. Reason: New leader de75341c7b3744f58d95dda11feca969. Latest consensus state: current_term: 1 leader_uuid: "de75341c7b3744f58d95dda11feca969" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de75341c7b3744f58d95dda11feca969" member_type: VOTER } }
I20260812 06:16:59.436337  2483 sys_catalog.cc:455] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "de75341c7b3744f58d95dda11feca969" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "de75341c7b3744f58d95dda11feca969" member_type: VOTER } }
I20260812 06:16:59.436498  2485 sys_catalog.cc:458] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:59.436542  2483 sys_catalog.cc:458] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [sys.catalog]: This master's current role is: LEADER
W20260812 06:16:59.438395  2499 catalog_manager.cc:1594] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:59.438493  2499 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:59.438618  2500 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:59.439620  2500 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:59.444973  2500 catalog_manager.cc:1383] Generated new cluster ID: 4c8f7a5be35548169ad80520ef8986f4
I20260812 06:16:59.445080  2500 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:59.460310  2500 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:59.461303  2500 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:59.470593  2500 catalog_manager.cc:6092] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: Generated new TSK 0
I20260812 06:16:59.471375  2500 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:59.501381  2403 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:59.504739  2505 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:16:59.504776  2403 server_base.cc:1061] running on GCE node
W20260812 06:16:59.504731  2504 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:16:59.504953  2508 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:16:59.505262  2403 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:59.505307  2403 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:16:59.505328  2403 hybrid_clock.cc:648] HybridClock initialized: now 1786515419505329 us; error 0 us; skew 500 ppm
I20260812 06:16:59.506477  2403 webserver.cc:533] Webserver started at http://127.2.88.193:41899/ using document root <none> and password file <none>
I20260812 06:16:59.506680  2403 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:59.506767  2403 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:59.506866  2403 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:59.507302  2403 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/instance:
uuid: "aa80147a3aee4ea5a3c369f6d1735d78"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-g350"
I20260812 06:16:59.509032  2403 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:59.510207  2513 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:16:59.510478  2403 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:16:59.510556  2403 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root
uuid: "aa80147a3aee4ea5a3c369f6d1735d78"
format_stamp: "Formatted at 2026-08-12 06:16:59 on dist-test-slave-g350"
I20260812 06:16:59.510659  2403 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-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:16:59.541483  2403 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:59.542017  2403 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:59.542568  2403 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:59.543531  2403 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:59.543587  2403 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.543656  2403 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:59.543695  2403 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:59.551260  2403 rpc_server.cc:307] RPC server started. Bound to: 127.2.88.193:34251
I20260812 06:16:59.551299  2581 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.88.193:34251 every 8 connection(s)
I20260812 06:16:59.562691  2582 heartbeater.cc:344] Connected to a master server at 127.2.88.254:42269
I20260812 06:16:59.563019  2582 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:59.563651  2582 heartbeater.cc:507] Master 127.2.88.254:42269 requested a full tablet report, sending...
I20260812 06:16:59.565641  2439 ts_manager.cc:194] Registered new tserver with Master: aa80147a3aee4ea5a3c369f6d1735d78 (127.2.88.193:34251)
I20260812 06:16:59.565922  2403 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013879332s
I20260812 06:16:59.567072  2439 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41104
I20260812 06:16:59.580305  2439 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41106:
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:16:59.597076  2543 tablet_service.cc:1511] Processing CreateTablet for tablet bc98e9133a96401ea3d6857194ff5cce (DEFAULT_TABLE table=heavy-update-compaction-test [id=f4dad6bea74643b1827cda6ac2ff919c]), partition=
I20260812 06:16:59.597685  2543 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet bc98e9133a96401ea3d6857194ff5cce. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:59.601557  2595 tablet_bootstrap.cc:492] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Bootstrap starting.
I20260812 06:16:59.602875  2595 tablet_bootstrap.cc:654] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:59.604408  2595 tablet_bootstrap.cc:492] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: No bootstrap required, opened a new log
I20260812 06:16:59.604553  2595 ts_tablet_manager.cc:1403] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:59.605161  2595 raft_consensus.cc:359] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa80147a3aee4ea5a3c369f6d1735d78" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 34251 } }
I20260812 06:16:59.605316  2595 raft_consensus.cc:385] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:59.605356  2595 raft_consensus.cc:740] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aa80147a3aee4ea5a3c369f6d1735d78, State: Initialized, Role: FOLLOWER
I20260812 06:16:59.605499  2595 consensus_queue.cc:260] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [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: "aa80147a3aee4ea5a3c369f6d1735d78" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 34251 } }
I20260812 06:16:59.605626  2595 raft_consensus.cc:399] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:59.605682  2595 raft_consensus.cc:493] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:59.605732  2595 raft_consensus.cc:3060] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:59.606859  2595 raft_consensus.cc:515] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa80147a3aee4ea5a3c369f6d1735d78" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 34251 } }
I20260812 06:16:59.607036  2595 leader_election.cc:304] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [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: aa80147a3aee4ea5a3c369f6d1735d78; no voters: 
I20260812 06:16:59.607273  2595 leader_election.cc:290] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:59.607465  2597 raft_consensus.cc:2804] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:59.607584  2595 ts_tablet_manager.cc:1434] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:16:59.607878  2582 heartbeater.cc:499] Master 127.2.88.254:42269 was elected leader, sending a full tablet report...
I20260812 06:16:59.608269  2597 raft_consensus.cc:697] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 1 LEADER]: Becoming Leader. State: Replica: aa80147a3aee4ea5a3c369f6d1735d78, State: Running, Role: LEADER
I20260812 06:16:59.608454  2597 consensus_queue.cc:237] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [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: "aa80147a3aee4ea5a3c369f6d1735d78" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 34251 } }
I20260812 06:16:59.612066  2439 catalog_manager.cc:5719] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 reported cstate change: term changed from 0 to 1, leader changed from <none> to aa80147a3aee4ea5a3c369f6d1735d78 (127.2.88.193). New cstate: current_term: 1 leader_uuid: "aa80147a3aee4ea5a3c369f6d1735d78" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa80147a3aee4ea5a3c369f6d1735d78" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 34251 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:59.713121  2403 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.078s	user 0.025s	sys 0.000s
I20260812 06:16:59.802809  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.125253
I20260812 06:17:00.040439  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.237s	user 0.175s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":3790,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1022,"drs_written":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4,"lbm_write_time_us":51154,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":556,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"spinlock_wait_cycles":4352,"thread_start_us":122,"threads_started":1,"update_count":1500}
I20260812 06:17:00.041869  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:00.059374  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.059935  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling LogGCOp(bc98e9133a96401ea3d6857194ff5cce): free 8725963 bytes of WAL
I20260812 06:17:00.060251  2518 log_reader.cc:385] T bc98e9133a96401ea3d6857194ff5cce: removed 1 log segments from log reader
I20260812 06:17:00.060320  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000001 (ops 1-6)
I20260812 06:17:00.063181  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: LogGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:00.063669  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce): 8206537 bytes on disk
I20260812 06:17:00.064510  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:00.065073  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:00.240338  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.175s	user 0.125s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":464,"lbm_write_time_us":32314,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":367,"threads_started":5,"update_count":2000}
I20260812 06:17:00.240870  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:00.293706  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.053s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":20319,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.294566  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:00.311215  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.311839  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:00.466997  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.155s	user 0.138s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590350,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":788,"lbm_read_time_us":11315,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30290,"lbm_writes_lt_1ms":443,"mutex_wait_us":130,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:00.467749  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:00.527010  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.059s	user 0.030s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21093,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.527905  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:00.540076  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.007s	sys 0.004s 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:17:00.540640  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:00.724242  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.183s	user 0.147s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":337,"lbm_read_time_us":12699,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34895,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":123648,"update_count":2000}
I20260812 06:17:00.724845  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:00.795389  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.070s	user 0.036s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23805,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:00.796206  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:00.808735  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:00.809546  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:00.963397  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.154s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":10493,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29260,"lbm_writes_lt_1ms":443,"mutex_wait_us":92,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:17:00.964264  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:01.016165  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.052s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21516,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.016873  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:01.031786  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.032825  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:01.195461  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.162s	user 0.139s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":10639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":33173,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:17:01.197989  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:01.237994  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.040s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19046,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.238606  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:01.252370  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.253026  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:01.397502  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.144s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":965,"lbm_read_time_us":9695,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30147,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2000}
I20260812 06:17:01.398371  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:01.454152  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.056s	user 0.024s	sys 0.031s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21455,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:01.454826  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:01.466099  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.466701  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:01.518486  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.052s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1530,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:01.519570  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling LogGCOp(bc98e9133a96401ea3d6857194ff5cce): free 112239308 bytes of WAL
I20260812 06:17:01.519901  2518 log_reader.cc:385] T bc98e9133a96401ea3d6857194ff5cce: removed 11 log segments from log reader
I20260812 06:17:01.519975  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000002 (ops 7-10)
I20260812 06:17:01.520020  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000003 (ops 11-15)
I20260812 06:17:01.520044  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000004 (ops 16-20)
I20260812 06:17:01.520067  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000005 (ops 21-25)
I20260812 06:17:01.520089  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000006 (ops 26-30)
I20260812 06:17:01.520116  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000007 (ops 31-35)
I20260812 06:17:01.520141  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000008 (ops 36-40)
I20260812 06:17:01.520164  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000009 (ops 41-45)
I20260812 06:17:01.520198  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000010 (ops 46-50)
I20260812 06:17:01.520221  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000011 (ops 51-55)
I20260812 06:17:01.520243  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000012 (ops 56-60)
I20260812 06:17:01.551790  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: LogGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:01.553292  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce): 448 bytes on disk
I20260812 06:17:01.553983  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:17:01.554595  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:01.571378  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.571981  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:01.798370  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.226s	user 0.169s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692880,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":298,"lbm_read_time_us":14366,"lbm_reads_lt_1ms":565,"lbm_write_time_us":38532,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":86,"threads_started":1,"update_count":2500}
I20260812 06:17:01.800649  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=14.095187
I20260812 06:17:01.871709  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.071s	user 0.025s	sys 0.042s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28430,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:01.872897  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:01.885983  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:01.886679  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:02.093952  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.207s	user 0.141s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1867,"lbm_read_time_us":14015,"lbm_reads_lt_1ms":572,"lbm_write_time_us":40993,"lbm_writes_lt_1ms":543,"mutex_wait_us":447,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:17:02.094600  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:02.152415  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.054s	user 0.041s	sys 0.009s Metrics: {"bytes_written":12471587,"delete_count":0,"lbm_write_time_us":23718,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1520}
I20260812 06:17:02.153257  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.198762  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.045s	user 0.008s	sys 0.019s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":9167,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":480}
I20260812 06:17:02.199427  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.216730  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.217456  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:02.406214  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.188s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692875,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":350,"lbm_read_time_us":14537,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32838,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:02.406955  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:02.455659  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.048s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20767,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:02.456386  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.474200  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.474917  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:02.635006  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.160s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":409,"lbm_read_time_us":8259,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30773,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.635735  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=11.118625
I20260812 06:17:02.679457  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.043s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16650,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:02.680020  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.699131  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.019s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.699816  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.710700  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4078,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:02.711323  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:02.872658  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.161s	user 0.121s	sys 0.029s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":497,"lbm_read_time_us":10894,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31358,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:02.873710  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=14.095187
I20260812 06:17:02.933838  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.060s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26940,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:02.934471  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:02.947089  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.947630  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:03.127866  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.180s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35135,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2500}
I20260812 06:17:03.128625  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=14.095187
I20260812 06:17:03.187326  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.058s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":29438,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.187887  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:03.200816  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.201625  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:03.233664  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.032s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1708,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1983,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:03.234488  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling LogGCOp(bc98e9133a96401ea3d6857194ff5cce): free 132118265 bytes of WAL
I20260812 06:17:03.234743  2518 log_reader.cc:385] T bc98e9133a96401ea3d6857194ff5cce: removed 13 log segments from log reader
I20260812 06:17:03.234794  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000013 (ops 61-65)
I20260812 06:17:03.234826  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000014 (ops 66-70)
I20260812 06:17:03.234896  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000015 (ops 71-74)
I20260812 06:17:03.234952  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000016 (ops 75-79)
I20260812 06:17:03.234992  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000017 (ops 80-84)
I20260812 06:17:03.235034  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000018 (ops 85-88)
I20260812 06:17:03.235074  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000019 (ops 89-93)
I20260812 06:17:03.235113  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000020 (ops 94-98)
I20260812 06:17:03.235152  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000021 (ops 99-103)
I20260812 06:17:03.235191  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000022 (ops 104-108)
I20260812 06:17:03.235229  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000023 (ops 109-113)
I20260812 06:17:03.235267  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000024 (ops 114-118)
I20260812 06:17:03.235306  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000025 (ops 119-122)
I20260812 06:17:03.267182  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: LogGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:03.267849  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=3.181125
I20260812 06:17:03.282598  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4553935,"delete_count":0,"lbm_write_time_us":5905,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:03.283156  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:03.295202  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:03.295775  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:03.550194  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.254s	user 0.168s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897814,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":504,"lbm_read_time_us":15374,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46183,"lbm_writes_lt_1ms":743,"mutex_wait_us":90,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8832,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:03.551628  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=18.063937
I20260812 06:17:03.635413  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.084s	user 0.046s	sys 0.035s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":35851,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.636067  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=3.181125
I20260812 06:17:03.658398  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5406,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:03.658993  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce): 472 bytes on disk
I20260812 06:17:03.659492  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:03.660126  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:03.672058  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.672716  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:03.882349  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.209s	user 0.169s	sys 0.039s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32897693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":985,"lbm_read_time_us":15362,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43255,"lbm_writes_lt_1ms":743,"mutex_wait_us":306,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3500}
I20260812 06:17:03.883183  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=15.087375
I20260812 06:17:03.941185  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.058s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":25878,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:17:03.941802  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:03.971849  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.030s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.972374  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:03.983726  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.984323  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:04.169838  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.185s	user 0.153s	sys 0.031s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":215,"lbm_read_time_us":13865,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38819,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":170880,"update_count":3000}
I20260812 06:17:04.170455  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=14.095187
I20260812 06:17:04.220395  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.050s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21956,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.221074  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:04.238562  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.239347  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:04.402290  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.163s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2007,"lbm_read_time_us":10774,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31159,"lbm_writes_lt_1ms":543,"mutex_wait_us":777,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78848,"update_count":2500}
I20260812 06:17:04.402918  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=11.118625
I20260812 06:17:04.450239  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.047s	user 0.026s	sys 0.019s Metrics: {"bytes_written":13292065,"delete_count":0,"lbm_write_time_us":20017,"lbm_writes_lt_1ms":327,"reinsert_count":0,"update_count":1620}
I20260812 06:17:04.451036  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.196750
I20260812 06:17:04.463654  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:04.464437  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:04.626371  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.162s	user 0.096s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590318,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":9682,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26678,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:04.627110  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=14.095187
I20260812 06:17:04.683646  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.056s	user 0.022s	sys 0.026s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22209,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.684192  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:04.705327  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4417,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.706174  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:04.746203  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushMRSOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.040s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1949,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1598,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:04.747107  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling LogGCOp(bc98e9133a96401ea3d6857194ff5cce): free 121006625 bytes of WAL
I20260812 06:17:04.747416  2518 log_reader.cc:385] T bc98e9133a96401ea3d6857194ff5cce: removed 12 log segments from log reader
I20260812 06:17:04.747479  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000026 (ops 123-127)
I20260812 06:17:04.747521  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000027 (ops 128-132)
I20260812 06:17:04.747545  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000028 (ops 133-137)
I20260812 06:17:04.747571  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000029 (ops 138-142)
I20260812 06:17:04.747599  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000030 (ops 143-146)
I20260812 06:17:04.747623  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000031 (ops 147-151)
I20260812 06:17:04.747645  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000032 (ops 152-156)
I20260812 06:17:04.747666  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000033 (ops 157-161)
I20260812 06:17:04.747704  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000034 (ops 162-166)
I20260812 06:17:04.747735  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000035 (ops 167-171)
I20260812 06:17:04.747771  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000036 (ops 172-176)
I20260812 06:17:04.747797  2518 log.cc:1079] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/bc98e9133a96401ea3d6857194ff5cce/wal-000000037 (ops 177-181)
I20260812 06:17:04.782809  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: LogGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.035s	user 0.003s	sys 0.031s Metrics: {}
I20260812 06:17:04.783340  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:04.813526  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.030s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.814155  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:04.825485  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.826282  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce): 463 bytes on disk
I20260812 06:17:04.826987  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: UndoDeltaBlockGCOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.828060  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:05.096421  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.268s	user 0.168s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897818,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1096,"lbm_read_time_us":18030,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44067,"lbm_writes_lt_1ms":743,"mutex_wait_us":131,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:17:05.097193  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=18.063937
I20260812 06:17:05.183642  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.086s	user 0.052s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":36099,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:05.184286  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=2.188937
I20260812 06:17:05.195598  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4283,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.196496  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce): perf score=1.000000
I20260812 06:17:05.348928  2403 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.636s	user 2.092s	sys 0.151s
I20260812 06:17:05.400581  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: MajorDeltaCompactionOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.204s	user 0.134s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795172,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":15726,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36321,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:05.401170  2583 maintenance_manager.cc:419] P aa80147a3aee4ea5a3c369f6d1735d78: Scheduling FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce): perf score=10.126437
I20260812 06:17:05.423316  2403 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.003s	sys 0.000s
I20260812 06:17:05.424069  2403 tablet_server.cc:179] TabletServer@127.2.88.193:0 shutting down...
I20260812 06:17:05.446592  2518 maintenance_manager.cc:643] P aa80147a3aee4ea5a3c369f6d1735d78: FlushDeltaMemStoresOp(bc98e9133a96401ea3d6857194ff5cce) complete. Timing: real 0.045s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16157,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.447518  2403 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:05.448045  2403 tablet_replica.cc:333] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78: stopping tablet replica
I20260812 06:17:05.448256  2403 raft_consensus.cc:2243] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:05.448482  2403 raft_consensus.cc:2272] T bc98e9133a96401ea3d6857194ff5cce P aa80147a3aee4ea5a3c369f6d1735d78 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:05.465960  2403 tablet_server.cc:196] TabletServer@127.2.88.193:0 shutdown complete.
I20260812 06:17:05.472064  2403 master.cc:562] Master@127.2.88.254:42269 shutting down...
I20260812 06:17:05.478468  2403 raft_consensus.cc:2243] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:05.478763  2403 raft_consensus.cc:2272] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:05.478859  2403 tablet_replica.cc:333] T 00000000000000000000000000000000 P de75341c7b3744f58d95dda11feca969: stopping tablet replica
I20260812 06:17:05.492709  2403 master.cc:584] Master@127.2.88.254:42269 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6231 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:05.589401  2403 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.88.254:46173
I20260812 06:17:05.589915  2403 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:05.592722  2618 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:05.592752  2615 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:05.592947  2403 server_base.cc:1061] running on GCE node
W20260812 06:17:05.592749  2616 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:05.593254  2403 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:05.593323  2403 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:05.593356  2403 hybrid_clock.cc:648] HybridClock initialized: now 1786515425593356 us; error 0 us; skew 500 ppm
I20260812 06:17:05.594652  2403 webserver.cc:533] Webserver started at http://127.2.88.254:35993/ using document root <none> and password file <none>
I20260812 06:17:05.594908  2403 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:05.594996  2403 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:05.595085  2403 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:05.595554  2403 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/master-0-root/instance:
uuid: "a28b519a41644074b0a882baf11b17cd"
format_stamp: "Formatted at 2026-08-12 06:17:05 on dist-test-slave-g350"
I20260812 06:17:05.598260  2403 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:05.599960  2623 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.600421  2403 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:17:05.600582  2403 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/master-0-root
uuid: "a28b519a41644074b0a882baf11b17cd"
format_stamp: "Formatted at 2026-08-12 06:17:05 on dist-test-slave-g350"
I20260812 06:17:05.600710  2403 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:05.615409  2403 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:05.615926  2403 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:05.621331  2403 rpc_server.cc:307] RPC server started. Bound to: 127.2.88.254:46173
I20260812 06:17:05.623502  2686 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.88.254:46173 every 8 connection(s)
I20260812 06:17:05.632385  2687 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:05.634953  2687 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd: Bootstrap starting.
I20260812 06:17:05.636101  2687 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:05.637452  2687 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd: No bootstrap required, opened a new log
I20260812 06:17:05.637943  2687 raft_consensus.cc:359] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER }
I20260812 06:17:05.638043  2687 raft_consensus.cc:385] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:05.638067  2687 raft_consensus.cc:740] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a28b519a41644074b0a882baf11b17cd, State: Initialized, Role: FOLLOWER
I20260812 06:17:05.638249  2687 consensus_queue.cc:260] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [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: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER }
I20260812 06:17:05.638365  2687 raft_consensus.cc:399] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:05.638399  2687 raft_consensus.cc:493] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:05.638435  2687 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:05.639585  2687 raft_consensus.cc:515] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER }
I20260812 06:17:05.639740  2687 leader_election.cc:304] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [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: a28b519a41644074b0a882baf11b17cd; no voters: 
I20260812 06:17:05.639947  2687 leader_election.cc:290] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:05.640158  2690 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:05.640446  2690 raft_consensus.cc:697] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 1 LEADER]: Becoming Leader. State: Replica: a28b519a41644074b0a882baf11b17cd, State: Running, Role: LEADER
I20260812 06:17:05.640470  2687 sys_catalog.cc:565] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:05.640651  2690 consensus_queue.cc:237] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [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: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER }
I20260812 06:17:05.641242  2693 sys_catalog.cc:455] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [sys.catalog]: SysCatalogTable state changed. Reason: New leader a28b519a41644074b0a882baf11b17cd. Latest consensus state: current_term: 1 leader_uuid: "a28b519a41644074b0a882baf11b17cd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER } }
I20260812 06:17:05.641337  2693 sys_catalog.cc:458] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:05.641480  2691 sys_catalog.cc:455] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a28b519a41644074b0a882baf11b17cd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a28b519a41644074b0a882baf11b17cd" member_type: VOTER } }
I20260812 06:17:05.641582  2691 sys_catalog.cc:458] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:05.642037  2699 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:05.642925  2699 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:05.643183  2403 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:05.645525  2699 catalog_manager.cc:1383] Generated new cluster ID: b6803d1ac1cb4bce92e254ade1de963f
I20260812 06:17:05.645637  2699 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:05.658565  2699 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:05.659277  2699 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:05.680244  2699 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd: Generated new TSK 0
I20260812 06:17:05.680567  2699 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:05.708689  2403 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:05.711093  2710 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:05.711159  2711 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:05.711187  2713 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:05.711411  2403 server_base.cc:1061] running on GCE node
I20260812 06:17:05.711700  2403 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:05.711750  2403 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:05.711774  2403 hybrid_clock.cc:648] HybridClock initialized: now 1786515425711774 us; error 0 us; skew 500 ppm
I20260812 06:17:05.712870  2403 webserver.cc:533] Webserver started at http://127.2.88.193:35623/ using document root <none> and password file <none>
I20260812 06:17:05.713078  2403 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:05.713155  2403 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:05.713244  2403 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:05.713784  2403 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/instance:
uuid: "4862cd2c60ae4c3f8fb0f7fa79076681"
format_stamp: "Formatted at 2026-08-12 06:17:05 on dist-test-slave-g350"
I20260812 06:17:05.715879  2403 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:05.717190  2719 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.717562  2403 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:05.717711  2403 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root
uuid: "4862cd2c60ae4c3f8fb0f7fa79076681"
format_stamp: "Formatted at 2026-08-12 06:17:05 on dist-test-slave-g350"
I20260812 06:17:05.717803  2403 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:05.725317  2403 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:05.725797  2403 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:05.726094  2403 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:05.726631  2403 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:05.726675  2403 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.726711  2403 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:05.726725  2403 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:05.734006  2403 rpc_server.cc:307] RPC server started. Bound to: 127.2.88.193:42439
I20260812 06:17:05.737192  2791 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.88.193:42439 every 8 connection(s)
I20260812 06:17:05.747757  2792 heartbeater.cc:344] Connected to a master server at 127.2.88.254:46173
I20260812 06:17:05.747912  2792 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:05.748274  2792 heartbeater.cc:507] Master 127.2.88.254:46173 requested a full tablet report, sending...
I20260812 06:17:05.749112  2641 ts_manager.cc:194] Registered new tserver with Master: 4862cd2c60ae4c3f8fb0f7fa79076681 (127.2.88.193:42439)
I20260812 06:17:05.749859  2403 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014758507s
I20260812 06:17:05.750140  2641 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46712
I20260812 06:17:05.760118  2641 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46722:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:05.772521  2753 tablet_service.cc:1511] Processing CreateTablet for tablet b0b1c6dfdbb14afc9b378b4fbfa8e5a3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5d854fa186264637a5dde250f987c39d]), partition=
I20260812 06:17:05.772847  2753 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b0b1c6dfdbb14afc9b378b4fbfa8e5a3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:05.775393  2806 tablet_bootstrap.cc:492] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Bootstrap starting.
I20260812 06:17:05.776463  2806 tablet_bootstrap.cc:654] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:05.778438  2806 tablet_bootstrap.cc:492] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: No bootstrap required, opened a new log
I20260812 06:17:05.778568  2806 ts_tablet_manager.cc:1403] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:05.779124  2806 raft_consensus.cc:359] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4862cd2c60ae4c3f8fb0f7fa79076681" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 42439 } }
I20260812 06:17:05.779250  2806 raft_consensus.cc:385] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:05.779275  2806 raft_consensus.cc:740] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4862cd2c60ae4c3f8fb0f7fa79076681, State: Initialized, Role: FOLLOWER
I20260812 06:17:05.779389  2806 consensus_queue.cc:260] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [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: "4862cd2c60ae4c3f8fb0f7fa79076681" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 42439 } }
I20260812 06:17:05.779498  2806 raft_consensus.cc:399] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:05.779557  2806 raft_consensus.cc:493] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:05.779630  2806 raft_consensus.cc:3060] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:05.780524  2806 raft_consensus.cc:515] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4862cd2c60ae4c3f8fb0f7fa79076681" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 42439 } }
I20260812 06:17:05.780686  2806 leader_election.cc:304] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [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: 4862cd2c60ae4c3f8fb0f7fa79076681; no voters: 
I20260812 06:17:05.781008  2806 leader_election.cc:290] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:05.781234  2808 raft_consensus.cc:2804] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:05.781384  2808 raft_consensus.cc:697] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 1 LEADER]: Becoming Leader. State: Replica: 4862cd2c60ae4c3f8fb0f7fa79076681, State: Running, Role: LEADER
I20260812 06:17:05.781419  2806 ts_tablet_manager.cc:1434] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:05.781471  2792 heartbeater.cc:499] Master 127.2.88.254:46173 was elected leader, sending a full tablet report...
I20260812 06:17:05.781531  2808 consensus_queue.cc:237] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [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: "4862cd2c60ae4c3f8fb0f7fa79076681" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 42439 } }
I20260812 06:17:05.783149  2640 catalog_manager.cc:5719] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4862cd2c60ae4c3f8fb0f7fa79076681 (127.2.88.193). New cstate: current_term: 1 leader_uuid: "4862cd2c60ae4c3f8fb0f7fa79076681" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4862cd2c60ae4c3f8fb0f7fa79076681" member_type: VOTER last_known_addr { host: "127.2.88.193" port: 42439 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:05.856068  2403 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.022s	sys 0.004s
I20260812 06:17:05.987979  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=15.086190
I20260812 06:17:06.167634  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.179s	user 0.130s	sys 0.043s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":912,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44636,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:17:06.168612  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): free 11976772 bytes of WAL
I20260812 06:17:06.168928  2724 log_reader.cc:385] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3: removed 1 log segments from log reader
I20260812 06:17:06.169001  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000001 (ops 1-6)
I20260812 06:17:06.171936  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:06.172600  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): 12308976 bytes on disk
I20260812 06:17:06.173194  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.173751  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:06.193415  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.019s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.193948  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:06.351619  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.158s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":747,"lbm_read_time_us":12054,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30145,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":442,"threads_started":5,"update_count":2000}
I20260812 06:17:06.352416  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=10.126437
I20260812 06:17:06.396677  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.397236  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:06.409792  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.410332  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:06.578822  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.168s	user 0.136s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":827,"lbm_read_time_us":11363,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27868,"lbm_writes_lt_1ms":443,"mutex_wait_us":114,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:17:06.579527  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=11.118625
I20260812 06:17:06.627125  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.047s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12717753,"delete_count":0,"lbm_write_time_us":21267,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:06.627698  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:06.642907  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.643622  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:06.792994  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.149s	user 0.122s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631321,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":9583,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28599,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2000}
I20260812 06:17:06.793934  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=10.126437
I20260812 06:17:06.846944  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.053s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18846,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.847538  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:06.860944  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.861542  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:06.998265  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.136s	user 0.116s	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":989,"lbm_read_time_us":9136,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25970,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24064,"update_count":2000}
I20260812 06:17:06.998855  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=10.126437
I20260812 06:17:07.052820  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.054s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19558,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.053350  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:07.064199  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.065014  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:07.201263  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.136s	user 0.108s	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":1044,"lbm_read_time_us":10194,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24481,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2000}
I20260812 06:17:07.202036  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=10.126437
I20260812 06:17:07.260524  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.058s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16492,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.261158  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:07.272815  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.273352  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:07.439934  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.166s	user 0.106s	sys 0.060s 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":818,"lbm_read_time_us":13000,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26528,"lbm_writes_lt_1ms":443,"mutex_wait_us":344,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.440507  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=10.126437
I20260812 06:17:07.492914  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.052s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18968,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.493543  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:07.510679  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.017s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.511508  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:07.541429  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.030s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":421,"dirs.run_wall_time_us":1588,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1574,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:07.542832  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): free 121006371 bytes of WAL
I20260812 06:17:07.543104  2724 log_reader.cc:385] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3: removed 12 log segments from log reader
I20260812 06:17:07.543151  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000002 (ops 7-11)
I20260812 06:17:07.543210  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000003 (ops 12-16)
I20260812 06:17:07.543267  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000004 (ops 17-21)
I20260812 06:17:07.543303  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000005 (ops 22-26)
I20260812 06:17:07.543341  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000006 (ops 27-31)
I20260812 06:17:07.543381  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000007 (ops 32-36)
I20260812 06:17:07.543424  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000008 (ops 37-40)
I20260812 06:17:07.543459  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000009 (ops 41-45)
I20260812 06:17:07.543498  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000010 (ops 46-50)
I20260812 06:17:07.543538  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000011 (ops 51-55)
I20260812 06:17:07.543576  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000012 (ops 56-60)
I20260812 06:17:07.543617  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000013 (ops 61-65)
I20260812 06:17:07.572752  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:07.573416  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=3.181125
I20260812 06:17:07.596861  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.023s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:07.597424  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:07.608500  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:07.609127  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:07.842459  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.233s	user 0.165s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":680,"lbm_read_time_us":17177,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39473,"lbm_writes_lt_1ms":643,"mutex_wait_us":271,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"thread_start_us":88,"threads_started":1,"update_count":3000}
I20260812 06:17:07.843034  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:07.907164  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.064s	user 0.029s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23829,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.907799  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:07.918988  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.919457  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): 448 bytes on disk
I20260812 06:17:07.919883  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.920347  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:08.140437  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.220s	user 0.129s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":498,"lbm_read_time_us":14411,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36412,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:17:08.141222  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:08.210595  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.069s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":23256,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.211417  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:08.233335  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.022s	user 0.001s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.234197  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:08.439802  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.205s	user 0.115s	sys 0.083s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733728,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":723,"lbm_read_time_us":14010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32058,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:08.440502  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:08.498431  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.058s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22611,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.498986  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:08.512471  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.513144  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:08.733958  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.221s	user 0.137s	sys 0.063s 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":307,"lbm_read_time_us":12083,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33527,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:17:08.734761  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:08.805781  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.071s	user 0.053s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28772,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.806556  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:08.820942  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.821544  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.007016  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.185s	user 0.116s	sys 0.053s 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":1333,"lbm_read_time_us":12605,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34535,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:17:09.008105  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:09.069348  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.061s	user 0.040s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21681,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.070251  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:09.086721  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.087293  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.269753  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.182s	user 0.145s	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":874,"lbm_read_time_us":13172,"lbm_reads_lt_1ms":564,"lbm_write_time_us":37421,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:17:09.270373  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:09.320334  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.050s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21237,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.321015  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:09.334182  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.335116  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.371536  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1838,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2394,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:09.372431  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): free 129320556 bytes of WAL
I20260812 06:17:09.372718  2724 log_reader.cc:385] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3: removed 13 log segments from log reader
I20260812 06:17:09.372794  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000014 (ops 66-70)
I20260812 06:17:09.372850  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000015 (ops 71-75)
I20260812 06:17:09.372888  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000016 (ops 76-80)
I20260812 06:17:09.372951  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000017 (ops 81-84)
I20260812 06:17:09.372991  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000018 (ops 85-89)
I20260812 06:17:09.373029  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000019 (ops 90-94)
I20260812 06:17:09.373066  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000020 (ops 95-98)
I20260812 06:17:09.373100  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000021 (ops 99-103)
I20260812 06:17:09.373134  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000022 (ops 104-108)
I20260812 06:17:09.373167  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000023 (ops 109-113)
I20260812 06:17:09.373221  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000024 (ops 114-118)
I20260812 06:17:09.373257  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000025 (ops 119-123)
I20260812 06:17:09.373296  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000026 (ops 124-128)
I20260812 06:17:09.405287  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:09.405834  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): 492 bytes on disk
I20260812 06:17:09.406411  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.407157  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=5.165500
I20260812 06:17:09.427486  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":7056402,"delete_count":0,"lbm_write_time_us":7980,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:17:09.428212  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.434408  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":1602,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:17:09.434932  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.662792  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.228s	user 0.149s	sys 0.074s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938716,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":684,"lbm_read_time_us":14949,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43823,"lbm_writes_lt_1ms":743,"mutex_wait_us":598,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19456,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:17:09.663479  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=15.087375
I20260812 06:17:09.729095  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.065s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16820147,"delete_count":0,"lbm_write_time_us":23885,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:09.730186  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=3.181125
I20260812 06:17:09.749104  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4266761,"delete_count":0,"lbm_write_time_us":7305,"lbm_writes_lt_1ms":107,"reinsert_count":0,"update_count":520}
I20260812 06:17:09.749694  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:09.762233  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":4880,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:17:09.762811  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:09.990772  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.228s	user 0.162s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836248,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":635,"lbm_read_time_us":17411,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38348,"lbm_writes_lt_1ms":643,"mutex_wait_us":272,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":3000}
I20260812 06:17:09.991430  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:10.053369  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.062s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28069,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.054349  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:10.073294  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.074002  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:10.265254  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.191s	user 0.142s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":637,"lbm_read_time_us":13638,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32748,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":54912,"update_count":2500}
I20260812 06:17:10.266003  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:10.338784  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.073s	user 0.043s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24745,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.339545  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:10.351171  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.351814  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:10.562129  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.210s	user 0.129s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733721,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":955,"lbm_read_time_us":14767,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30287,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30848,"update_count":2500}
I20260812 06:17:10.563089  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:10.631150  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.068s	user 0.016s	sys 0.048s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22457,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.631855  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:10.643757  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.644379  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:10.859899  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.215s	user 0.156s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1360,"lbm_read_time_us":13894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35050,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:10.860561  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=14.095187
I20260812 06:17:10.921476  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.061s	user 0.031s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23401,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.922192  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:10.934823  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.935563  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:10.974733  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushMRSOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.039s	user 0.025s	sys 0.002s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":136,"dirs.run_cpu_time_us":327,"dirs.run_wall_time_us":2260,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1579,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:10.975630  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): free 115490376 bytes of WAL
I20260812 06:17:10.976099  2724 log_reader.cc:385] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3: removed 11 log segments from log reader
I20260812 06:17:10.976163  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000027 (ops 129-132)
I20260812 06:17:10.976202  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000028 (ops 133-137)
I20260812 06:17:10.976228  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000029 (ops 138-142)
I20260812 06:17:10.976263  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000030 (ops 143-147)
I20260812 06:17:10.976303  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000031 (ops 148-152)
I20260812 06:17:10.976336  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000032 (ops 153-157)
I20260812 06:17:10.976358  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000033 (ops 158-162)
I20260812 06:17:10.976390  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000034 (ops 163-167)
I20260812 06:17:10.976425  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000035 (ops 168-172)
I20260812 06:17:10.976464  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000036 (ops 173-177)
I20260812 06:17:10.976496  2724 log.cc:1079] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: Deleting log segment in path: /tmp/dist-test-taskgcoQB1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515419345888-2403-0/minicluster-data/ts-0-root/wals/b0b1c6dfdbb14afc9b378b4fbfa8e5a3/wal-000000037 (ops 178-182)
I20260812 06:17:11.005649  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: LogGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:11.006228  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): 448 bytes on disk
I20260812 06:17:11.006696  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: UndoDeltaBlockGCOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.007555  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:11.023366  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.023959  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:11.252887  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.229s	user 0.142s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836254,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":680,"lbm_read_time_us":15016,"lbm_reads_lt_1ms":665,"lbm_write_time_us":37604,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:11.253772  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=18.063937
I20260812 06:17:11.323653  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.069s	user 0.038s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32701,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:11.324259  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=2.188937
I20260812 06:17:11.340433  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: FlushDeltaMemStoresOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.340996  2794 maintenance_manager.cc:419] P 4862cd2c60ae4c3f8fb0f7fa79076681: Scheduling MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3): perf score=1.000000
I20260812 06:17:11.413663  2403 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.557s	user 2.045s	sys 0.197s
I20260812 06:17:11.492035  2403 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.001s	sys 0.000s
I20260812 06:17:11.492628  2403 tablet_server.cc:179] TabletServer@127.2.88.193:0 shutting down...
I20260812 06:17:11.531397  2724 maintenance_manager.cc:643] P 4862cd2c60ae4c3f8fb0f7fa79076681: MajorDeltaCompactionOp(b0b1c6dfdbb14afc9b378b4fbfa8e5a3) complete. Timing: real 0.190s	user 0.150s	sys 0.040s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":594,"lbm_read_time_us":13971,"lbm_reads_lt_1ms":660,"lbm_write_time_us":32344,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":33408,"update_count":3000}
I20260812 06:17:11.532120  2403 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:11.532501  2403 tablet_replica.cc:333] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681: stopping tablet replica
I20260812 06:17:11.532688  2403 raft_consensus.cc:2243] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:11.533000  2403 raft_consensus.cc:2272] T b0b1c6dfdbb14afc9b378b4fbfa8e5a3 P 4862cd2c60ae4c3f8fb0f7fa79076681 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:11.550513  2403 tablet_server.cc:196] TabletServer@127.2.88.193:0 shutdown complete.
I20260812 06:17:11.585855  2403 master.cc:562] Master@127.2.88.254:46173 shutting down...
I20260812 06:17:11.589735  2403 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:11.589982  2403 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:11.590094  2403 tablet_replica.cc:333] T 00000000000000000000000000000000 P a28b519a41644074b0a882baf11b17cd: stopping tablet replica
I20260812 06:17:11.603214  2403 master.cc:584] Master@127.2.88.254:46173 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6114 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12347 ms total)

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