[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:16.663880 23476 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.237.62:40665
I20260812 06:19:16.664884 23476 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:16.665483 23476 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:16.671403 23490 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:16.671403 23487 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:16.671693 23486 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:16.671720 23476 server_base.cc:1061] running on GCE node
I20260812 06:19:16.672237 23476 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:16.672376 23476 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:16.672427 23476 hybrid_clock.cc:648] HybridClock initialized: now 1786515556672425 us; error 0 us; skew 500 ppm
I20260812 06:19:16.674108 23476 webserver.cc:533] Webserver started at http://127.22.237.62:33955/ using document root <none> and password file <none>
I20260812 06:19:16.674623 23476 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:16.674703 23476 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:16.674947 23476 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:16.676625 23476 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/master-0-root/instance:
uuid: "b30512bb779349eeb4006dc45b497866"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-45dx"
I20260812 06:19:16.680160 23476 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:16.682125 23498 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.683075 23476 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:16.683216 23476 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/master-0-root
uuid: "b30512bb779349eeb4006dc45b497866"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-45dx"
I20260812 06:19:16.683319 23476 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:16.696978 23476 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:16.697558 23476 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:16.697739 23476 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:16.705421 23476 rpc_server.cc:307] RPC server started. Bound to: 127.22.237.62:40665
I20260812 06:19:16.705430 23594 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.237.62:40665 every 8 connection(s)
I20260812 06:19:16.707602 23595 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:16.713276 23595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: Bootstrap starting.
I20260812 06:19:16.715617 23595 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:16.716624 23595 log.cc:826] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:16.718261 23595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: No bootstrap required, opened a new log
I20260812 06:19:16.721060 23595 raft_consensus.cc:359] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b30512bb779349eeb4006dc45b497866" member_type: VOTER }
I20260812 06:19:16.721225 23595 raft_consensus.cc:385] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:16.721351 23595 raft_consensus.cc:740] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b30512bb779349eeb4006dc45b497866, State: Initialized, Role: FOLLOWER
I20260812 06:19:16.721971 23595 consensus_queue.cc:260] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [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: "b30512bb779349eeb4006dc45b497866" member_type: VOTER }
I20260812 06:19:16.722142 23595 raft_consensus.cc:399] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:16.722220 23595 raft_consensus.cc:493] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:16.722386 23595 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:16.723182 23595 raft_consensus.cc:515] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b30512bb779349eeb4006dc45b497866" member_type: VOTER }
I20260812 06:19:16.723624 23595 leader_election.cc:304] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [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: b30512bb779349eeb4006dc45b497866; no voters: 
I20260812 06:19:16.723937 23595 leader_election.cc:290] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:16.724066 23601 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:16.724337 23601 raft_consensus.cc:697] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 1 LEADER]: Becoming Leader. State: Replica: b30512bb779349eeb4006dc45b497866, State: Running, Role: LEADER
I20260812 06:19:16.724798 23601 consensus_queue.cc:237] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [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: "b30512bb779349eeb4006dc45b497866" member_type: VOTER }
I20260812 06:19:16.724916 23595 sys_catalog.cc:565] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:16.726653 23602 sys_catalog.cc:455] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b30512bb779349eeb4006dc45b497866" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b30512bb779349eeb4006dc45b497866" member_type: VOTER } }
I20260812 06:19:16.726687 23603 sys_catalog.cc:455] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b30512bb779349eeb4006dc45b497866. Latest consensus state: current_term: 1 leader_uuid: "b30512bb779349eeb4006dc45b497866" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b30512bb779349eeb4006dc45b497866" member_type: VOTER } }
I20260812 06:19:16.726770 23602 sys_catalog.cc:458] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:16.726783 23603 sys_catalog.cc:458] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:16.727427 23476 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:16.727936 23621 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:16.729949 23621 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:16.734148 23621 catalog_manager.cc:1383] Generated new cluster ID: 2ec22b1aa8544c16bbf0d423de755f09
I20260812 06:19:16.734213 23621 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:16.741245 23621 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:16.742314 23621 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:16.752755 23621 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: Generated new TSK 0
I20260812 06:19:16.753443 23621 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:16.759979 23476 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:16.762609 23629 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:16.762669 23632 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:16.762722 23636 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:16.762952 23476 server_base.cc:1061] running on GCE node
I20260812 06:19:16.763137 23476 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:16.763197 23476 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:16.763232 23476 hybrid_clock.cc:648] HybridClock initialized: now 1786515556763231 us; error 0 us; skew 500 ppm
I20260812 06:19:16.764137 23476 webserver.cc:533] Webserver started at http://127.22.237.1:39581/ using document root <none> and password file <none>
I20260812 06:19:16.764361 23476 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:16.764428 23476 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:16.764511 23476 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:16.764884 23476 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/instance:
uuid: "0e017f29143c4a72bbbc64046c68dc96"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-45dx"
I20260812 06:19:16.766407 23476 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:16.767403 23644 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.767710 23476 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:16.767772 23476 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root
uuid: "0e017f29143c4a72bbbc64046c68dc96"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-45dx"
I20260812 06:19:16.767858 23476 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:16.781944 23476 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:16.782670 23476 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:16.783190 23476 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:16.784039 23476 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:16.784091 23476 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.784163 23476 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:16.784207 23476 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.790970 23476 rpc_server.cc:307] RPC server started. Bound to: 127.22.237.1:40859
I20260812 06:19:16.791003 23750 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.237.1:40859 every 8 connection(s)
I20260812 06:19:16.800733 23762 heartbeater.cc:344] Connected to a master server at 127.22.237.62:40665
I20260812 06:19:16.800992 23762 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:16.801457 23762 heartbeater.cc:507] Master 127.22.237.62:40665 requested a full tablet report, sending...
I20260812 06:19:16.802858 23528 ts_manager.cc:194] Registered new tserver with Master: 0e017f29143c4a72bbbc64046c68dc96 (127.22.237.1:40859)
I20260812 06:19:16.803193 23476 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011579244s
I20260812 06:19:16.804100 23528 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35492
I20260812 06:19:16.813160 23528 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35498:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:16.828523 23697 tablet_service.cc:1511] Processing CreateTablet for tablet 0505dc7fd6f94266af65154889d065a5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=370c0fae77af433eab048e075fd9b83b]), partition=
I20260812 06:19:16.829064 23697 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0505dc7fd6f94266af65154889d065a5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:16.831267 23785 tablet_bootstrap.cc:492] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Bootstrap starting.
I20260812 06:19:16.832250 23785 tablet_bootstrap.cc:654] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:16.833487 23785 tablet_bootstrap.cc:492] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: No bootstrap required, opened a new log
I20260812 06:19:16.833595 23785 ts_tablet_manager.cc:1403] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:16.834034 23785 raft_consensus.cc:359] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e017f29143c4a72bbbc64046c68dc96" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 40859 } }
I20260812 06:19:16.834148 23785 raft_consensus.cc:385] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:16.834172 23785 raft_consensus.cc:740] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0e017f29143c4a72bbbc64046c68dc96, State: Initialized, Role: FOLLOWER
I20260812 06:19:16.834342 23785 consensus_queue.cc:260] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [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: "0e017f29143c4a72bbbc64046c68dc96" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 40859 } }
I20260812 06:19:16.834437 23785 raft_consensus.cc:399] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:16.834506 23785 raft_consensus.cc:493] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:16.834558 23785 raft_consensus.cc:3060] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:16.835300 23785 raft_consensus.cc:515] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e017f29143c4a72bbbc64046c68dc96" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 40859 } }
I20260812 06:19:16.835450 23785 leader_election.cc:304] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [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: 0e017f29143c4a72bbbc64046c68dc96; no voters: 
I20260812 06:19:16.835693 23785 leader_election.cc:290] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:16.835947 23788 raft_consensus.cc:2804] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:16.836056 23785 ts_tablet_manager.cc:1434] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:16.836236 23788 raft_consensus.cc:697] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 1 LEADER]: Becoming Leader. State: Replica: 0e017f29143c4a72bbbc64046c68dc96, State: Running, Role: LEADER
I20260812 06:19:16.836480 23788 consensus_queue.cc:237] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [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: "0e017f29143c4a72bbbc64046c68dc96" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 40859 } }
I20260812 06:19:16.836570 23762 heartbeater.cc:499] Master 127.22.237.62:40665 was elected leader, sending a full tablet report...
I20260812 06:19:16.839098 23528 catalog_manager.cc:5719] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0e017f29143c4a72bbbc64046c68dc96 (127.22.237.1). New cstate: current_term: 1 leader_uuid: "0e017f29143c4a72bbbc64046c68dc96" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0e017f29143c4a72bbbc64046c68dc96" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 40859 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:16.912127 23476 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.022s	sys 0.010s
I20260812 06:19:17.042096 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushMRSOp(0505dc7fd6f94266af65154889d065a5): perf score=17.070565
I20260812 06:19:17.192138 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushMRSOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.150s	user 0.138s	sys 0.008s Metrics: {"bytes_written":9107611,"cfile_init":1,"compiler_manager_pool.queue_time_us":685,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1082,"drs_written":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36077,"lbm_writes_lt_1ms":679,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":152448,"thread_start_us":149,"threads_started":1,"update_count":1110}
I20260812 06:19:17.193202 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling LogGCOp(0505dc7fd6f94266af65154889d065a5): free 20290830 bytes of WAL
I20260812 06:19:17.193513 23651 log_reader.cc:385] T 0505dc7fd6f94266af65154889d065a5: removed 2 log segments from log reader
I20260812 06:19:17.193584 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000001 (ops 1-6)
I20260812 06:19:17.193652 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000002 (ops 7-10)
I20260812 06:19:17.198760 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: LogGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:17.199201 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.223938 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":5072,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:17.224387 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5): 16411392 bytes on disk
I20260812 06:19:17.224936 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:17.225327 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.239076 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.239442 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:17.363523 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.124s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672375,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":435,"lbm_read_time_us":7923,"lbm_reads_lt_1ms":469,"lbm_write_time_us":21670,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":288,"threads_started":5,"update_count":2000}
I20260812 06:19:17.363992 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:17.414922 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.051s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16548,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:17.415452 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.427336 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.427917 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:17.551569 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.123s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":10132,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22476,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:19:17.552191 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:17.587402 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.035s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15282,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.588017 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.597882 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.598519 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:17.717707 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.119s	user 0.101s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":7530,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23606,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:17.718262 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:17.767329 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.049s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17398,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.768013 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.778992 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.779596 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:17.931926 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.152s	user 0.103s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":11721,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24931,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.932498 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:17.978962 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.046s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16050,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.979415 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:17.989499 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.990253 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:18.106060 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.116s	user 0.104s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":291,"lbm_read_time_us":8124,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21704,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:18.106775 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:18.153689 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19159,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.154346 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.166646 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.167213 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:18.305804 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.138s	user 0.120s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":997,"lbm_read_time_us":10840,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22969,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:19:18.306607 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:18.345415 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.039s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16343,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.345932 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.356127 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.356614 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushMRSOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:18.388415 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushMRSOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.032s	user 0.023s	sys 0.007s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":183,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1230,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1860,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:18.389148 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling LogGCOp(0505dc7fd6f94266af65154889d065a5): free 112692318 bytes of WAL
I20260812 06:19:18.389367 23651 log_reader.cc:385] T 0505dc7fd6f94266af65154889d065a5: removed 11 log segments from log reader
I20260812 06:19:18.389412 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000003 (ops 11-15)
I20260812 06:19:18.389439 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000004 (ops 16-20)
I20260812 06:19:18.389509 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000005 (ops 21-25)
I20260812 06:19:18.389552 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000006 (ops 26-30)
I20260812 06:19:18.389599 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000007 (ops 31-35)
I20260812 06:19:18.389652 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000008 (ops 36-40)
I20260812 06:19:18.389691 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000009 (ops 41-45)
I20260812 06:19:18.389730 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000010 (ops 46-50)
I20260812 06:19:18.389778 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000011 (ops 51-55)
I20260812 06:19:18.389818 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000012 (ops 56-60)
I20260812 06:19:18.389858 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000013 (ops 61-65)
I20260812 06:19:18.411412 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: LogGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:18.411824 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5): 447 bytes on disk
I20260812 06:19:18.412245 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.412791 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.427489 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.427875 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.437598 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.437964 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:18.615520 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.177s	user 0.120s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":473,"lbm_read_time_us":12157,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34416,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:18.616199 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:18.666085 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.049s	user 0.016s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18339,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.666590 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.680913 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.681365 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:18.833338 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.152s	user 0.101s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":9365,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29625,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:18.833940 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=11.118625
I20260812 06:19:18.878583 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.044s	user 0.016s	sys 0.025s Metrics: {"bytes_written":13456167,"delete_count":0,"lbm_write_time_us":19308,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":330,"mutex_wait_us":867,"reinsert_count":0,"update_count":1640}
I20260812 06:19:18.879144 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.895762 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.016s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3364209,"delete_count":0,"lbm_write_time_us":3540,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:19:18.896241 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:18.905381 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3364,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.905810 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:19.066251 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.160s	user 0.102s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774781,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":213,"lbm_read_time_us":11936,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26965,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:19:19.066854 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:19.122192 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.055s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21085,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.122715 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:19.133402 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.133841 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:19.300287 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.166s	user 0.123s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":917,"lbm_read_time_us":13196,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27669,"lbm_writes_lt_1ms":543,"mutex_wait_us":385,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:19.300872 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:19.363832 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.063s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":23232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.364415 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:19.374908 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.375319 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:19.538789 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.163s	user 0.118s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":13009,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27046,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:19.539402 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=11.118625
I20260812 06:19:19.567545 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.028s	user 0.014s	sys 0.011s Metrics: {"bytes_written":12553635,"delete_count":0,"lbm_write_time_us":12331,"lbm_writes_lt_1ms":309,"reinsert_count":0,"update_count":1530}
I20260812 06:19:19.568008 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:19.580289 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:19.580816 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:19.732450 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.151s	user 0.097s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":9934,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23593,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:19:19.733213 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=11.118625
I20260812 06:19:19.775688 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17973,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:19.776365 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:19.794836 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.018s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4982,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.795363 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:19.805365 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.805774 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushMRSOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:19.837615 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushMRSOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1299,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2090,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:19.838279 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling LogGCOp(0505dc7fd6f94266af65154889d065a5): free 132571380 bytes of WAL
I20260812 06:19:19.838500 23651 log_reader.cc:385] T 0505dc7fd6f94266af65154889d065a5: removed 13 log segments from log reader
I20260812 06:19:19.838544 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000014 (ops 66-70)
I20260812 06:19:19.838572 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000015 (ops 71-75)
I20260812 06:19:19.838635 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000016 (ops 76-80)
I20260812 06:19:19.838670 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000017 (ops 81-85)
I20260812 06:19:19.838708 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000018 (ops 86-90)
I20260812 06:19:19.838759 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000019 (ops 91-95)
I20260812 06:19:19.838799 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000020 (ops 96-100)
I20260812 06:19:19.838850 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000021 (ops 101-104)
I20260812 06:19:19.838887 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000022 (ops 105-109)
I20260812 06:19:19.838925 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000023 (ops 110-114)
I20260812 06:19:19.838964 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000024 (ops 115-119)
I20260812 06:19:19.839002 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000025 (ops 120-124)
I20260812 06:19:19.839040 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000026 (ops 125-128)
I20260812 06:19:19.866987 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: LogGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:19.867350 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=4.173312
I20260812 06:19:19.893919 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.026s	user 0.001s	sys 0.024s Metrics: {"bytes_written":5415441,"delete_count":0,"lbm_write_time_us":6363,"lbm_writes_lt_1ms":135,"reinsert_count":0,"update_count":660}
I20260812 06:19:19.894480 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5): 483 bytes on disk
I20260812 06:19:19.894990 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.895520 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=1.196750
I20260812 06:19:19.907548 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:19.908134 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:20.122555 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.214s	user 0.121s	sys 0.093s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979832,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":824,"lbm_read_time_us":14459,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39091,"lbm_writes_lt_1ms":743,"mutex_wait_us":271,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:19:20.123387 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:20.173866 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.050s	user 0.017s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17940,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.174482 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:20.187179 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.187615 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:20.371312 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.184s	user 0.122s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":12236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32495,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:19:20.371968 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:20.430508 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.058s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19187,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.431035 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:20.441179 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.441594 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:20.630105 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.188s	user 0.115s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":11875,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30872,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:20.630836 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:20.679064 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.048s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.679551 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:20.698262 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.019s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.698864 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:20.880446 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.181s	user 0.087s	sys 0.086s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":286,"lbm_read_time_us":13022,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29785,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:20.881152 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:20.929960 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.049s	user 0.022s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18371,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.930454 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:20.940888 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.941490 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:21.126271 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.184s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":10890,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30891,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:19:21.126914 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:21.173749 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.047s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18867,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.174472 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:21.186429 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.186954 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:21.332463 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.145s	user 0.102s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":532,"lbm_read_time_us":10988,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26909,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:21.333280 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=14.095187
I20260812 06:19:21.380590 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.047s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":18846,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.381084 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:21.395129 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.395735 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushMRSOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:21.425043 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushMRSOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":299,"dirs.run_cpu_time_us":154,"dirs.run_wall_time_us":1285,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1707,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:21.425773 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling LogGCOp(0505dc7fd6f94266af65154889d065a5): free 129773842 bytes of WAL
I20260812 06:19:21.426060 23651 log_reader.cc:385] T 0505dc7fd6f94266af65154889d065a5: removed 13 log segments from log reader
I20260812 06:19:21.426121 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000027 (ops 129-133)
I20260812 06:19:21.426158 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000028 (ops 134-138)
I20260812 06:19:21.426190 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000029 (ops 139-142)
I20260812 06:19:21.426216 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000030 (ops 143-147)
I20260812 06:19:21.426246 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000031 (ops 148-152)
I20260812 06:19:21.426290 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000032 (ops 153-157)
I20260812 06:19:21.426328 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000033 (ops 158-162)
I20260812 06:19:21.426357 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000034 (ops 163-167)
I20260812 06:19:21.426385 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000035 (ops 168-172)
I20260812 06:19:21.426411 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000036 (ops 173-177)
I20260812 06:19:21.426441 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000037 (ops 178-182)
I20260812 06:19:21.426473 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000038 (ops 183-187)
I20260812 06:19:21.426505 23651 log.cc:1079] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/0505dc7fd6f94266af65154889d065a5/wal-000000039 (ops 188-192)
I20260812 06:19:21.456413 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: LogGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:21.456835 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5): 492 bytes on disk
I20260812 06:19:21.457329 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: UndoDeltaBlockGCOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:19:21.458190 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:21.475951 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.476541 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=2.188937
I20260812 06:19:21.487975 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.488649 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5): perf score=1.000000
I20260812 06:19:21.626814 23476 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.715s	user 1.739s	sys 0.173s
I20260812 06:19:21.704196 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: MajorDeltaCompactionOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.215s	user 0.161s	sys 0.049s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979753,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":5073,"lbm_read_time_us":12655,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36794,"lbm_writes_lt_1ms":743,"mutex_wait_us":2303,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:19:21.705197 23763 maintenance_manager.cc:419] P 0e017f29143c4a72bbbc64046c68dc96: Scheduling FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5): perf score=10.126437
I20260812 06:19:21.714308 23476 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.002s	sys 0.000s
I20260812 06:19:21.714957 23476 tablet_server.cc:179] TabletServer@127.22.237.1:0 shutting down...
I20260812 06:19:21.741029 23651 maintenance_manager.cc:643] P 0e017f29143c4a72bbbc64046c68dc96: FlushDeltaMemStoresOp(0505dc7fd6f94266af65154889d065a5) complete. Timing: real 0.036s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14830,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.741752 23476 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:21.742182 23476 tablet_replica.cc:333] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96: stopping tablet replica
I20260812 06:19:21.742419 23476 raft_consensus.cc:2243] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.742659 23476 raft_consensus.cc:2272] T 0505dc7fd6f94266af65154889d065a5 P 0e017f29143c4a72bbbc64046c68dc96 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.749655 23476 tablet_server.cc:196] TabletServer@127.22.237.1:0 shutdown complete.
I20260812 06:19:21.760921 23476 master.cc:562] Master@127.22.237.62:40665 shutting down...
I20260812 06:19:21.765273 23476 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.765419 23476 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.765475 23476 tablet_replica.cc:333] T 00000000000000000000000000000000 P b30512bb779349eeb4006dc45b497866: stopping tablet replica
I20260812 06:19:21.777534 23476 master.cc:584] Master@127.22.237.62:40665 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5197 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:21.872676 23476 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.237.62:41681
I20260812 06:19:21.873127 23476 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.875478 23820 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.875552 23476 server_base.cc:1061] running on GCE node
W20260812 06:19:21.875455 23818 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:21.875453 23817 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.875846 23476 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.875921 23476 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:21.875947 23476 hybrid_clock.cc:648] HybridClock initialized: now 1786515561875947 us; error 0 us; skew 500 ppm
I20260812 06:19:21.877398 23476 webserver.cc:533] Webserver started at http://127.22.237.62:32809/ using document root <none> and password file <none>
I20260812 06:19:21.877585 23476 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.877655 23476 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.877733 23476 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.878120 23476 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/master-0-root/instance:
uuid: "3bf393903c414a7c8c644dc77b58ef57"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-45dx"
I20260812 06:19:21.879590 23476 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:21.880539 23826 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.880796 23476 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:21.880888 23476 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/master-0-root
uuid: "3bf393903c414a7c8c644dc77b58ef57"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-45dx"
I20260812 06:19:21.880976 23476 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:21.893513 23476 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.893880 23476 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.898164 23476 rpc_server.cc:307] RPC server started. Bound to: 127.22.237.62:41681
I20260812 06:19:21.901178 23942 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:21.901548 23941 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.237.62:41681 every 8 connection(s)
I20260812 06:19:21.905189 23942 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57: Bootstrap starting.
I20260812 06:19:21.905969 23942 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.906924 23942 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57: No bootstrap required, opened a new log
I20260812 06:19:21.907315 23942 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER }
I20260812 06:19:21.907403 23942 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.907467 23942 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3bf393903c414a7c8c644dc77b58ef57, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.907660 23942 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [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: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER }
I20260812 06:19:21.907748 23942 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.907809 23942 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.907867 23942 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.908620 23942 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER }
I20260812 06:19:21.908782 23942 leader_election.cc:304] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [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: 3bf393903c414a7c8c644dc77b58ef57; no voters: 
I20260812 06:19:21.908994 23942 leader_election.cc:290] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.909137 23947 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.909365 23947 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 1 LEADER]: Becoming Leader. State: Replica: 3bf393903c414a7c8c644dc77b58ef57, State: Running, Role: LEADER
I20260812 06:19:21.909444 23942 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:21.909561 23947 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [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: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER }
I20260812 06:19:21.910038 23948 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3bf393903c414a7c8c644dc77b58ef57" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER } }
I20260812 06:19:21.910090 23950 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3bf393903c414a7c8c644dc77b58ef57. Latest consensus state: current_term: 1 leader_uuid: "3bf393903c414a7c8c644dc77b58ef57" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3bf393903c414a7c8c644dc77b58ef57" member_type: VOTER } }
I20260812 06:19:21.910229 23950 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.910499 23960 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:21.910703 23948 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.911424 23960 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:21.911612 23476 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:21.913234 23960 catalog_manager.cc:1383] Generated new cluster ID: aa198269791d40d392c9765551bd184a
I20260812 06:19:21.913295 23960 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:21.930986 23960 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:21.931556 23960 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:21.939263 23960 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57: Generated new TSK 0
I20260812 06:19:21.939456 23960 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:21.943955 23476 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.946081 23973 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.946126 23476 server_base.cc:1061] running on GCE node
W20260812 06:19:21.946177 23974 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:21.946095 23978 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.946386 23476 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.946456 23476 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:21.946501 23476 hybrid_clock.cc:648] HybridClock initialized: now 1786515561946500 us; error 0 us; skew 500 ppm
I20260812 06:19:21.947350 23476 webserver.cc:533] Webserver started at http://127.22.237.1:38293/ using document root <none> and password file <none>
I20260812 06:19:21.947530 23476 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.947605 23476 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.947691 23476 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.948100 23476 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/instance:
uuid: "ac0ff2827eec4b6997ea63008a524ebb"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-45dx"
I20260812 06:19:21.949649 23476 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:21.950543 23988 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.950794 23476 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:21.950896 23476 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root
uuid: "ac0ff2827eec4b6997ea63008a524ebb"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-45dx"
I20260812 06:19:21.950991 23476 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:21.967278 23476 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.967643 23476 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.967947 23476 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:21.968459 23476 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:21.968526 23476 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.968585 23476 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:21.968633 23476 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.974628 23476 rpc_server.cc:307] RPC server started. Bound to: 127.22.237.1:42169
I20260812 06:19:21.975296 24109 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.237.1:42169 every 8 connection(s)
I20260812 06:19:21.984486 24112 heartbeater.cc:344] Connected to a master server at 127.22.237.62:41681
I20260812 06:19:21.984578 24112 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:21.984768 24112 heartbeater.cc:507] Master 127.22.237.62:41681 requested a full tablet report, sending...
I20260812 06:19:21.985368 23857 ts_manager.cc:194] Registered new tserver with Master: ac0ff2827eec4b6997ea63008a524ebb (127.22.237.1:42169)
I20260812 06:19:21.986059 23857 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45336
I20260812 06:19:21.986337 23476 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010957443s
I20260812 06:19:21.992910 23857 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45352:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:22.000942 24042 tablet_service.cc:1511] Processing CreateTablet for tablet dd9ae34a2ccc45828d0fbdc53748ec45 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ae81000f6a1f4991baeb5eba950f31f2]), partition=
I20260812 06:19:22.001169 24042 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dd9ae34a2ccc45828d0fbdc53748ec45. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:22.003000 24128 tablet_bootstrap.cc:492] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Bootstrap starting.
I20260812 06:19:22.003997 24128 tablet_bootstrap.cc:654] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:22.005110 24128 tablet_bootstrap.cc:492] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: No bootstrap required, opened a new log
I20260812 06:19:22.005208 24128 ts_tablet_manager.cc:1403] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:22.005654 24128 raft_consensus.cc:359] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac0ff2827eec4b6997ea63008a524ebb" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 42169 } }
I20260812 06:19:22.005744 24128 raft_consensus.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:22.005805 24128 raft_consensus.cc:740] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ac0ff2827eec4b6997ea63008a524ebb, State: Initialized, Role: FOLLOWER
I20260812 06:19:22.005983 24128 consensus_queue.cc:260] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [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: "ac0ff2827eec4b6997ea63008a524ebb" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 42169 } }
I20260812 06:19:22.006058 24128 raft_consensus.cc:399] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:22.006083 24128 raft_consensus.cc:493] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:22.006162 24128 raft_consensus.cc:3060] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:22.007089 24128 raft_consensus.cc:515] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac0ff2827eec4b6997ea63008a524ebb" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 42169 } }
I20260812 06:19:22.007205 24128 leader_election.cc:304] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [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: ac0ff2827eec4b6997ea63008a524ebb; no voters: 
I20260812 06:19:22.007354 24128 leader_election.cc:290] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:22.007494 24134 raft_consensus.cc:2804] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:22.007676 24128 ts_tablet_manager.cc:1434] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:22.007714 24112 heartbeater.cc:499] Master 127.22.237.62:41681 was elected leader, sending a full tablet report...
I20260812 06:19:22.007714 24134 raft_consensus.cc:697] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 1 LEADER]: Becoming Leader. State: Replica: ac0ff2827eec4b6997ea63008a524ebb, State: Running, Role: LEADER
I20260812 06:19:22.007946 24134 consensus_queue.cc:237] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [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: "ac0ff2827eec4b6997ea63008a524ebb" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 42169 } }
I20260812 06:19:22.009338 23857 catalog_manager.cc:5719] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb reported cstate change: term changed from 0 to 1, leader changed from <none> to ac0ff2827eec4b6997ea63008a524ebb (127.22.237.1). New cstate: current_term: 1 leader_uuid: "ac0ff2827eec4b6997ea63008a524ebb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac0ff2827eec4b6997ea63008a524ebb" member_type: VOTER last_known_addr { host: "127.22.237.1" port: 42169 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:22.067955 23476 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.015s	sys 0.008s
I20260812 06:19:22.225811 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=19.054940
I20260812 06:19:22.381970 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.156s	user 0.107s	sys 0.048s Metrics: {"bytes_written":13127963,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":879,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38992,"lbm_writes_lt_1ms":787,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":13568,"update_count":1600}
I20260812 06:19:22.382845 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): free 20743880 bytes of WAL
I20260812 06:19:22.383126 23997 log_reader.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45: removed 2 log segments from log reader
I20260812 06:19:22.383190 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000001 (ops 1-6)
I20260812 06:19:22.383239 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000002 (ops 7-11)
I20260812 06:19:22.389099 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:22.389444 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:22.400414 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3177,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:22.400801 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): 16821646 bytes on disk
I20260812 06:19:22.401161 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.401528 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:22.557505 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.156s	user 0.093s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713245,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":457,"lbm_read_time_us":10552,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25633,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":296,"threads_started":5,"update_count":2000}
I20260812 06:19:22.558068 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:22.618220 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.060s	user 0.022s	sys 0.029s Metrics: {"bytes_written":15999660,"delete_count":0,"lbm_write_time_us":22868,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":392,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1950}
I20260812 06:19:22.618780 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:22.630077 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.630534 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:22.795215 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.164s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405442,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":11640,"lbm_reads_lt_1ms":562,"lbm_write_time_us":25706,"lbm_writes_lt_1ms":533,"mutex_wait_us":39,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":45568,"update_count":2450}
I20260812 06:19:22.795935 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:22.853394 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.057s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20301,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.853979 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:22.871263 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.871843 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:23.054603 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.183s	user 0.118s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":12027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28558,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:19:23.055292 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:23.100245 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.045s	user 0.038s	sys 0.000s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18436,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.100920 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:23.121361 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.122000 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:23.298367 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.176s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":12131,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28125,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:19:23.299024 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:23.348155 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.049s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18294,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.348691 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:23.359582 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.360234 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:23.528872 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.168s	user 0.109s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":753,"lbm_read_time_us":9685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24619,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:23.529452 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:23.588438 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.059s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21266,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.588963 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:23.603060 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.603610 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:23.635720 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1224,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2004,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:23.636427 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): free 112692366 bytes of WAL
I20260812 06:19:23.636672 23997 log_reader.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45: removed 11 log segments from log reader
I20260812 06:19:23.636744 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000003 (ops 12-16)
I20260812 06:19:23.636794 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000004 (ops 17-21)
I20260812 06:19:23.636833 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000005 (ops 22-26)
I20260812 06:19:23.636873 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000006 (ops 27-31)
I20260812 06:19:23.636910 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000007 (ops 32-36)
I20260812 06:19:23.636951 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000008 (ops 37-41)
I20260812 06:19:23.636991 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000009 (ops 42-46)
I20260812 06:19:23.637030 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000010 (ops 47-51)
I20260812 06:19:23.637068 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000011 (ops 52-56)
I20260812 06:19:23.637118 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000012 (ops 57-61)
I20260812 06:19:23.637157 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000013 (ops 62-66)
I20260812 06:19:23.660956 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.024s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:23.661360 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): 447 bytes on disk
I20260812 06:19:23.661999 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.662551 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:23.691617 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.029s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.692056 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): free 11564875 bytes of WAL
I20260812 06:19:23.692260 23997 log_reader.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45: removed 1 log segments from log reader
I20260812 06:19:23.692334 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000014 (ops 67-70)
I20260812 06:19:23.694384 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:23.694641 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:23.706063 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.706729 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:23.930431 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.223s	user 0.172s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":882,"lbm_read_time_us":14173,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35778,"lbm_writes_lt_1ms":743,"mutex_wait_us":50,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:19:23.931157 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=18.063937
I20260812 06:19:23.994865 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.063s	user 0.049s	sys 0.012s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":28694,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:23.995344 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:24.007409 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.007941 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:24.210508 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.202s	user 0.127s	sys 0.074s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":14379,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33514,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3000}
I20260812 06:19:24.211335 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=15.087375
I20260812 06:19:24.251163 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.040s	user 0.032s	sys 0.005s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":17892,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:24.251657 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:24.267386 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.267908 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:24.437788 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.170s	user 0.102s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815670,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1276,"lbm_read_time_us":11308,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29718,"lbm_writes_lt_1ms":543,"mutex_wait_us":525,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:24.438402 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:24.495854 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.057s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25394,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.496649 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:24.510452 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.510957 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:24.681571 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.170s	user 0.122s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":13094,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26994,"lbm_writes_lt_1ms":543,"mutex_wait_us":398,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:24.682310 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:24.738900 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.056s	user 0.020s	sys 0.034s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20968,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.739506 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:24.750216 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.750654 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:24.920754 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.170s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":12095,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27245,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":99200,"update_count":2500}
I20260812 06:19:24.921494 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:24.973428 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.052s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24121,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.973976 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:24.992717 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.019s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.993148 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:25.023138 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1228,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1384,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:25.023762 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): free 112239316 bytes of WAL
I20260812 06:19:25.023998 23997 log_reader.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45: removed 11 log segments from log reader
I20260812 06:19:25.024045 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000015 (ops 71-75)
I20260812 06:19:25.024073 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000016 (ops 76-80)
I20260812 06:19:25.024128 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000017 (ops 81-85)
I20260812 06:19:25.024171 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000018 (ops 86-90)
I20260812 06:19:25.024196 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000019 (ops 91-95)
I20260812 06:19:25.024255 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000020 (ops 96-100)
I20260812 06:19:25.024281 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000021 (ops 101-105)
I20260812 06:19:25.024345 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000022 (ops 106-110)
I20260812 06:19:25.024384 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000023 (ops 111-115)
I20260812 06:19:25.024421 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000024 (ops 116-120)
I20260812 06:19:25.024459 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000025 (ops 121-124)
I20260812 06:19:25.049351 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.025s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:25.051874 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): 448 bytes on disk
I20260812 06:19:25.052500 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:19:25.053164 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=3.181125
I20260812 06:19:25.065747 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:25.066157 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:25.075461 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3539,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.075875 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:25.310484 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.234s	user 0.171s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":334,"lbm_read_time_us":17548,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39980,"lbm_writes_lt_1ms":743,"mutex_wait_us":116,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14592,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:19:25.311158 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=16.079562
I20260812 06:19:25.374790 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.063s	user 0.037s	sys 0.017s Metrics: {"bytes_written":18502131,"delete_count":0,"lbm_write_time_us":25367,"lbm_writes_lt_1ms":454,"reinsert_count":0,"update_count":2255}
I20260812 06:19:25.375461 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.196750
I20260812 06:19:25.386467 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.011s	user 0.002s	sys 0.003s Metrics: {"bytes_written":2420633,"delete_count":0,"lbm_write_time_us":2365,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:25.386915 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:25.399675 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4954,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.400050 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:25.628536 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.228s	user 0.124s	sys 0.092s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918164,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":658,"lbm_read_time_us":13584,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35617,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":3000}
I20260812 06:19:25.629237 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=18.063937
I20260812 06:19:25.700598 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.071s	user 0.034s	sys 0.025s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26622,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:25.701143 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:25.712890 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.713528 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:25.927572 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.214s	user 0.130s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":13967,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33936,"lbm_writes_lt_1ms":643,"mutex_wait_us":108,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:19:25.928414 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=18.063937
I20260812 06:19:25.996409 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.068s	user 0.046s	sys 0.013s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26347,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:25.996914 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:26.007246 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.007773 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:26.215201 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.207s	user 0.134s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1101,"lbm_read_time_us":15008,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34488,"lbm_writes_lt_1ms":643,"mutex_wait_us":290,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":3000}
I20260812 06:19:26.216087 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:26.268808 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.053s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22978,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.269366 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:26.286924 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.287465 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:26.453985 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.166s	user 0.133s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":12763,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26616,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:19:26.454813 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=14.095187
I20260812 06:19:26.505263 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.050s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22411,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:26.505801 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:26.534165 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.028s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.534647 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=2.188937
I20260812 06:19:26.544855 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.545287 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:26.577718 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushMRSOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2065,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:26.578397 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): free 129320714 bytes of WAL
I20260812 06:19:26.578637 23997 log_reader.cc:385] T dd9ae34a2ccc45828d0fbdc53748ec45: removed 13 log segments from log reader
I20260812 06:19:26.578684 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000026 (ops 125-129)
I20260812 06:19:26.578712 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000027 (ops 130-134)
I20260812 06:19:26.578776 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000028 (ops 135-139)
I20260812 06:19:26.578820 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000029 (ops 140-144)
I20260812 06:19:26.578862 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000030 (ops 145-149)
I20260812 06:19:26.578926 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000031 (ops 150-154)
I20260812 06:19:26.578984 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000032 (ops 155-159)
I20260812 06:19:26.579020 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000033 (ops 160-164)
I20260812 06:19:26.579059 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000034 (ops 165-168)
I20260812 06:19:26.579099 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000035 (ops 169-173)
I20260812 06:19:26.579138 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000036 (ops 174-178)
I20260812 06:19:26.579177 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000037 (ops 179-182)
I20260812 06:19:26.579219 23997 log.cc:1079] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: Deleting log segment in path: /tmp/dist-test-taskuF5BGC/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556653418-23476-0/minicluster-data/ts-0-root/wals/dd9ae34a2ccc45828d0fbdc53748ec45/wal-000000038 (ops 183-187)
I20260812 06:19:26.607384 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: LogGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:26.607848 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45): 482 bytes on disk
I20260812 06:19:26.608254 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: UndoDeltaBlockGCOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.608821 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=4.173312
I20260812 06:19:26.622525 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":5661585,"delete_count":0,"lbm_write_time_us":5724,"lbm_writes_lt_1ms":141,"reinsert_count":0,"update_count":690}
I20260812 06:19:26.622897 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.196750
I20260812 06:19:26.631506 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3190,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:19:26.631969 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=1.000000
I20260812 06:19:26.878983 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: MajorDeltaCompactionOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.247s	user 0.179s	sys 0.064s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123239,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":660,"lbm_read_time_us":18757,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44143,"lbm_writes_lt_1ms":843,"mutex_wait_us":75,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":92,"threads_started":1,"update_count":4000}
I20260812 06:19:26.882596 24113 maintenance_manager.cc:419] P ac0ff2827eec4b6997ea63008a524ebb: Scheduling FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45): perf score=19.056125
I20260812 06:19:26.893942 23476 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.826s	user 1.813s	sys 0.181s
I20260812 06:19:26.926301 23476 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.032s	user 0.003s	sys 0.000s
I20260812 06:19:26.926887 23476 tablet_server.cc:179] TabletServer@127.22.237.1:0 shutting down...
I20260812 06:19:26.933589 23997 maintenance_manager.cc:643] P ac0ff2827eec4b6997ea63008a524ebb: FlushDeltaMemStoresOp(dd9ae34a2ccc45828d0fbdc53748ec45) complete. Timing: real 0.051s	user 0.038s	sys 0.011s Metrics: {"bytes_written":20922560,"delete_count":0,"lbm_write_time_us":22577,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:19:26.934036 23476 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:26.934249 23476 tablet_replica.cc:333] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb: stopping tablet replica
I20260812 06:19:26.934363 23476 raft_consensus.cc:2243] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:26.934551 23476 raft_consensus.cc:2272] T dd9ae34a2ccc45828d0fbdc53748ec45 P ac0ff2827eec4b6997ea63008a524ebb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:26.938400 23476 tablet_server.cc:196] TabletServer@127.22.237.1:0 shutdown complete.
I20260812 06:19:26.948977 23476 master.cc:562] Master@127.22.237.62:41681 shutting down...
I20260812 06:19:26.952123 23476 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:26.952256 23476 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:26.952350 23476 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3bf393903c414a7c8c644dc77b58ef57: stopping tablet replica
I20260812 06:19:26.964550 23476 master.cc:584] Master@127.22.237.62:41681 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5187 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10386 ms total)

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