[==========] 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:20:23.762399 15725 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.91.126:39581
I20260812 06:20:23.763525 15725 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:20:23.764204 15725 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:23.771097 15725 server_base.cc:1061] running on GCE node
W20260812 06:20:23.771127 15731 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:20:23.771154 15730 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:20:23.771440 15733 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:20:23.772007 15725 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:23.772131 15725 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:20:23.772182 15725 hybrid_clock.cc:648] HybridClock initialized: now 1786515623772180 us; error 0 us; skew 500 ppm
I20260812 06:20:23.774129 15725 webserver.cc:533] Webserver started at http://127.15.91.126:44393/ using document root <none> and password file <none>
I20260812 06:20:23.774699 15725 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:23.774792 15725 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:23.775072 15725 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:23.776835 15725 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/master-0-root/instance:
uuid: "e695dfad257743c18e49220aaa759709"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-bxbt"
I20260812 06:20:23.780378 15725 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:20:23.782410 15738 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:20:23.783447 15725 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:23.783581 15725 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/master-0-root
uuid: "e695dfad257743c18e49220aaa759709"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-bxbt"
I20260812 06:20:23.783706 15725 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-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:20:23.817414 15725 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:23.818111 15725 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:20:23.818318 15725 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:23.825953 15725 rpc_server.cc:307] RPC server started. Bound to: 127.15.91.126:39581
I20260812 06:20:23.825961 15790 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.91.126:39581 every 8 connection(s)
I20260812 06:20:23.828239 15791 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:20:23.833617 15791 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: Bootstrap starting.
I20260812 06:20:23.836022 15791 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:23.836926 15791 log.cc:826] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:23.838608 15791 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: No bootstrap required, opened a new log
I20260812 06:20:23.841387 15791 raft_consensus.cc:359] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e695dfad257743c18e49220aaa759709" member_type: VOTER }
I20260812 06:20:23.841547 15791 raft_consensus.cc:385] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:23.841656 15791 raft_consensus.cc:740] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e695dfad257743c18e49220aaa759709, State: Initialized, Role: FOLLOWER
I20260812 06:20:23.842345 15791 consensus_queue.cc:260] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [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: "e695dfad257743c18e49220aaa759709" member_type: VOTER }
I20260812 06:20:23.842494 15791 raft_consensus.cc:399] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:23.842597 15791 raft_consensus.cc:493] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:23.842764 15791 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:23.843576 15791 raft_consensus.cc:515] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e695dfad257743c18e49220aaa759709" member_type: VOTER }
I20260812 06:20:23.844055 15791 leader_election.cc:304] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [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: e695dfad257743c18e49220aaa759709; no voters: 
I20260812 06:20:23.844406 15791 leader_election.cc:290] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:23.844568 15794 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:23.844870 15794 raft_consensus.cc:697] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 1 LEADER]: Becoming Leader. State: Replica: e695dfad257743c18e49220aaa759709, State: Running, Role: LEADER
I20260812 06:20:23.845286 15794 consensus_queue.cc:237] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [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: "e695dfad257743c18e49220aaa759709" member_type: VOTER }
I20260812 06:20:23.845429 15791 sys_catalog.cc:565] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:23.847342 15795 sys_catalog.cc:455] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e695dfad257743c18e49220aaa759709" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e695dfad257743c18e49220aaa759709" member_type: VOTER } }
I20260812 06:20:23.847453 15795 sys_catalog.cc:458] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:23.847384 15796 sys_catalog.cc:455] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e695dfad257743c18e49220aaa759709. Latest consensus state: current_term: 1 leader_uuid: "e695dfad257743c18e49220aaa759709" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e695dfad257743c18e49220aaa759709" member_type: VOTER } }
I20260812 06:20:23.847540 15796 sys_catalog.cc:458] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:23.847923 15725 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:23.847932 15808 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:23.850113 15808 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:23.854841 15808 catalog_manager.cc:1383] Generated new cluster ID: 1474833d9bbd40da8c7b3c66c0251109
I20260812 06:20:23.854914 15808 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:23.870746 15808 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:23.871958 15808 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:23.882653 15808 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: Generated new TSK 0
I20260812 06:20:23.883571 15808 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:23.912940 15725 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:23.915650 15813 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:20:23.915746 15816 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:20:23.915855 15814 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:23.915992 15725 server_base.cc:1061] running on GCE node
I20260812 06:20:23.916270 15725 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:23.916330 15725 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:20:23.916348 15725 hybrid_clock.cc:648] HybridClock initialized: now 1786515623916348 us; error 0 us; skew 500 ppm
I20260812 06:20:23.917452 15725 webserver.cc:533] Webserver started at http://127.15.91.65:43633/ using document root <none> and password file <none>
I20260812 06:20:23.917639 15725 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:23.917688 15725 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:23.917793 15725 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:23.918215 15725 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/instance:
uuid: "5c88e43f06f84678b1d6006c04094eb8"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-bxbt"
I20260812 06:20:23.919816 15725 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:23.920881 15821 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:20:23.921135 15725 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:23.921213 15725 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root
uuid: "5c88e43f06f84678b1d6006c04094eb8"
format_stamp: "Formatted at 2026-08-12 06:20:23 on dist-test-slave-bxbt"
I20260812 06:20:23.921311 15725 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-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:20:23.927266 15725 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:23.927858 15725 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:23.928371 15725 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:23.929271 15725 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:23.929327 15725 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:23.929404 15725 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:23.929440 15725 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:23.936357 15725 rpc_server.cc:307] RPC server started. Bound to: 127.15.91.65:44719
I20260812 06:20:23.936395 15884 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.91.65:44719 every 8 connection(s)
I20260812 06:20:23.951056 15885 heartbeater.cc:344] Connected to a master server at 127.15.91.126:39581
I20260812 06:20:23.951370 15885 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:23.951932 15885 heartbeater.cc:507] Master 127.15.91.126:39581 requested a full tablet report, sending...
I20260812 06:20:23.953449 15755 ts_manager.cc:194] Registered new tserver with Master: 5c88e43f06f84678b1d6006c04094eb8 (127.15.91.65:44719)
I20260812 06:20:23.953765 15725 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01673798s
I20260812 06:20:23.954733 15755 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54940
I20260812 06:20:23.964591 15755 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54944:
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:20:23.980289 15849 tablet_service.cc:1511] Processing CreateTablet for tablet 9a96ebe40c4c4d08b327f10dc70a11ab (DEFAULT_TABLE table=heavy-update-compaction-test [id=9c3749b8c5c84a22a8df23f4cb85c65c]), partition=
I20260812 06:20:23.980799 15849 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9a96ebe40c4c4d08b327f10dc70a11ab. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:23.983348 15897 tablet_bootstrap.cc:492] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Bootstrap starting.
I20260812 06:20:23.984684 15897 tablet_bootstrap.cc:654] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:23.986142 15897 tablet_bootstrap.cc:492] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: No bootstrap required, opened a new log
I20260812 06:20:23.986299 15897 ts_tablet_manager.cc:1403] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:23.986847 15897 raft_consensus.cc:359] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c88e43f06f84678b1d6006c04094eb8" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44719 } }
I20260812 06:20:23.986986 15897 raft_consensus.cc:385] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:23.987020 15897 raft_consensus.cc:740] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5c88e43f06f84678b1d6006c04094eb8, State: Initialized, Role: FOLLOWER
I20260812 06:20:23.987244 15897 consensus_queue.cc:260] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [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: "5c88e43f06f84678b1d6006c04094eb8" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44719 } }
I20260812 06:20:23.987356 15897 raft_consensus.cc:399] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:23.987440 15897 raft_consensus.cc:493] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:23.987502 15897 raft_consensus.cc:3060] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:23.988656 15897 raft_consensus.cc:515] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c88e43f06f84678b1d6006c04094eb8" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44719 } }
I20260812 06:20:23.988821 15897 leader_election.cc:304] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [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: 5c88e43f06f84678b1d6006c04094eb8; no voters: 
I20260812 06:20:23.989046 15897 leader_election.cc:290] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:23.989224 15899 raft_consensus.cc:2804] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:23.989392 15897 ts_tablet_manager.cc:1434] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:20:23.989498 15899 raft_consensus.cc:697] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 1 LEADER]: Becoming Leader. State: Replica: 5c88e43f06f84678b1d6006c04094eb8, State: Running, Role: LEADER
I20260812 06:20:23.989670 15885 heartbeater.cc:499] Master 127.15.91.126:39581 was elected leader, sending a full tablet report...
I20260812 06:20:23.989831 15899 consensus_queue.cc:237] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [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: "5c88e43f06f84678b1d6006c04094eb8" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44719 } }
I20260812 06:20:23.993006 15755 catalog_manager.cc:5719] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5c88e43f06f84678b1d6006c04094eb8 (127.15.91.65). New cstate: current_term: 1 leader_uuid: "5c88e43f06f84678b1d6006c04094eb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c88e43f06f84678b1d6006c04094eb8" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44719 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:24.057262 15725 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.016s	sys 0.010s
I20260812 06:20:24.187477 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=19.054940
I20260812 06:20:24.382774 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.195s	user 0.158s	sys 0.027s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":298,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1077,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46412,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":131,"threads_started":1,"update_count":1500}
I20260812 06:20:24.384109 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): free 20743880 bytes of WAL
I20260812 06:20:24.384439 15826 log_reader.cc:385] T 9a96ebe40c4c4d08b327f10dc70a11ab: removed 2 log segments from log reader
I20260812 06:20:24.384502 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000001 (ops 1-6)
I20260812 06:20:24.384562 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000002 (ops 7-11)
I20260812 06:20:24.390213 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:24.390626 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): 16411392 bytes on disk
I20260812 06:20:24.391237 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.391711 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=3.181125
I20260812 06:20:24.417066 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.025s	user 0.016s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6563,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:24.417680 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:24.433771 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6151,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.434412 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:24.609756 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.175s	user 0.138s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":467,"lbm_read_time_us":12245,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30029,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":327,"threads_started":5,"update_count":2500}
I20260812 06:20:24.610383 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:24.649510 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17049,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.650043 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:24.664832 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.665297 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:24.800115 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.135s	user 0.100s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1046,"lbm_read_time_us":8523,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26015,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:20:24.800868 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:24.846093 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.045s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16198,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.846606 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:24.857543 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.858140 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:24.982381 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.124s	user 0.089s	sys 0.035s 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":139,"lbm_read_time_us":8957,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23345,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:20:24.983083 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:25.018074 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15091,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.018646 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:25.032238 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.032647 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:25.154778 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.122s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":8061,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24203,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:20:25.155560 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:25.198279 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.042s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15324,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.198856 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:25.209582 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.210212 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:25.359884 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.149s	user 0.105s	sys 0.044s 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":240,"lbm_read_time_us":10213,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25409,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:25.360527 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:25.400058 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.039s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.400506 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:25.411191 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.411950 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:25.539086 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.127s	user 0.086s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":437,"lbm_read_time_us":8683,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23998,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:20:25.539892 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=10.126437
I20260812 06:20:25.586897 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.047s	user 0.033s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19658,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.587564 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:25.610302 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.022s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.610879 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:25.661374 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.050s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1363,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1635,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:25.662201 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): free 120553374 bytes of WAL
I20260812 06:20:25.662443 15826 log_reader.cc:385] T 9a96ebe40c4c4d08b327f10dc70a11ab: removed 12 log segments from log reader
I20260812 06:20:25.662492 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000003 (ops 12-16)
I20260812 06:20:25.662523 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000004 (ops 17-20)
I20260812 06:20:25.662591 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000005 (ops 21-25)
I20260812 06:20:25.662649 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000006 (ops 26-30)
I20260812 06:20:25.662689 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000007 (ops 31-35)
I20260812 06:20:25.662748 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000008 (ops 36-40)
I20260812 06:20:25.662786 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000009 (ops 41-44)
I20260812 06:20:25.662874 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000010 (ops 45-49)
I20260812 06:20:25.662914 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000011 (ops 50-54)
I20260812 06:20:25.662954 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000012 (ops 55-59)
I20260812 06:20:25.662995 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000013 (ops 60-64)
I20260812 06:20:25.663039 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000014 (ops 65-69)
I20260812 06:20:25.686919 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:25.687371 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): 472 bytes on disk
I20260812 06:20:25.688050 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":224,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.688694 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=6.157687
I20260812 06:20:25.708251 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.019s	user 0.019s	sys 0.000s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":8267,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:25.708725 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:25.722229 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.722806 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:25.914628 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.192s	user 0.121s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979755,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":434,"lbm_read_time_us":11810,"lbm_reads_lt_1ms":766,"lbm_write_time_us":39758,"lbm_writes_lt_1ms":743,"mutex_wait_us":66,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:20:25.915421 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:25.972972 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.057s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24472,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.973587 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=3.181125
I20260812 06:20:25.992251 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.992707 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:26.002583 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3673,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.003011 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:26.167224 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.164s	user 0.136s	sys 0.024s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":367,"lbm_read_time_us":12292,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33644,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:20:26.167902 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:26.219525 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.051s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25328,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.220094 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:26.235627 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.236351 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:26.401018 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.164s	user 0.127s	sys 0.020s 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":1089,"lbm_read_time_us":11229,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28323,"lbm_writes_lt_1ms":543,"mutex_wait_us":553,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:20:26.401613 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:26.459898 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.058s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20669,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:26.460443 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:26.472129 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.472627 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:26.648017 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.175s	user 0.124s	sys 0.044s 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":1084,"lbm_read_time_us":11539,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27883,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.648777 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:26.710444 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.061s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.710980 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:26.722462 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.722945 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:26.898943 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.176s	user 0.127s	sys 0.040s 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":1077,"lbm_read_time_us":10793,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32724,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:26.899663 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:26.951944 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.052s	user 0.040s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19196,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.952602 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:26.970592 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7053,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.971131 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:27.008322 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1142,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2017,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:27.009052 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): free 112239265 bytes of WAL
I20260812 06:20:27.009276 15826 log_reader.cc:385] T 9a96ebe40c4c4d08b327f10dc70a11ab: removed 11 log segments from log reader
I20260812 06:20:27.009335 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000015 (ops 70-74)
I20260812 06:20:27.009390 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000016 (ops 75-79)
I20260812 06:20:27.009428 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000017 (ops 80-84)
I20260812 06:20:27.009470 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000018 (ops 85-88)
I20260812 06:20:27.009511 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000019 (ops 89-93)
I20260812 06:20:27.009552 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000020 (ops 94-98)
I20260812 06:20:27.009591 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000021 (ops 99-103)
I20260812 06:20:27.009631 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000022 (ops 104-108)
I20260812 06:20:27.009671 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000023 (ops 109-113)
I20260812 06:20:27.009711 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000024 (ops 114-118)
I20260812 06:20:27.009750 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000025 (ops 119-123)
I20260812 06:20:27.032702 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:27.033221 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): 446 bytes on disk
I20260812 06:20:27.033748 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.034396 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=3.181125
I20260812 06:20:27.047235 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4307780,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:20:27.047758 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:27.058641 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:20:27.059299 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:27.264608 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.205s	user 0.125s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":664,"lbm_read_time_us":15040,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37223,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":158,"threads_started":1,"update_count":3500}
I20260812 06:20:27.265398 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=15.087375
I20260812 06:20:27.313536 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.048s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":20823,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:27.314182 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:27.337280 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.023s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.337821 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:27.348657 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.349184 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:27.522189 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.172s	user 0.105s	sys 0.066s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":563,"lbm_read_time_us":13870,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35730,"lbm_writes_lt_1ms":643,"mutex_wait_us":83,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:20:27.522879 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:27.580025 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.057s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26402,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.580595 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:27.599942 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.600765 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:27.752964 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.152s	user 0.092s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":8671,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29071,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:27.753590 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:27.808727 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.055s	user 0.033s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24368,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.809320 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:27.950066 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.141s	user 0.092s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":553,"lbm_read_time_us":9026,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23612,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:20:27.953565 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:28.000646 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.047s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23467,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.001398 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:28.022426 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.021s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.023348 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:28.198915 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.175s	user 0.116s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":686,"lbm_read_time_us":12763,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31668,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:20:28.199605 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:28.251420 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.052s	user 0.018s	sys 0.021s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18581,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.252030 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:28.267782 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.268417 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:28.429785 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.161s	user 0.105s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":272,"lbm_read_time_us":9814,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32880,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:20:28.430424 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=11.118625
I20260812 06:20:28.466511 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.036s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15750,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.467069 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:28.491104 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.491578 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=2.188937
I20260812 06:20:28.501762 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.502241 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:28.537487 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushMRSOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.035s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1249,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1725,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:28.538390 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): free 141338765 bytes of WAL
I20260812 06:20:28.538697 15826 log_reader.cc:385] T 9a96ebe40c4c4d08b327f10dc70a11ab: removed 14 log segments from log reader
I20260812 06:20:28.538780 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000026 (ops 124-128)
I20260812 06:20:28.538964 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000027 (ops 129-132)
I20260812 06:20:28.539059 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000028 (ops 133-137)
I20260812 06:20:28.539105 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000029 (ops 138-142)
I20260812 06:20:28.539144 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000030 (ops 143-146)
I20260812 06:20:28.539184 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000031 (ops 147-151)
I20260812 06:20:28.539224 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000032 (ops 152-156)
I20260812 06:20:28.539265 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000033 (ops 157-161)
I20260812 06:20:28.539305 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000034 (ops 162-166)
I20260812 06:20:28.539352 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000035 (ops 167-171)
I20260812 06:20:28.539392 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000036 (ops 172-176)
I20260812 06:20:28.539431 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000037 (ops 177-181)
I20260812 06:20:28.539474 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000038 (ops 182-186)
I20260812 06:20:28.539513 15826 log.cc:1079] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/9a96ebe40c4c4d08b327f10dc70a11ab/wal-000000039 (ops 187-191)
I20260812 06:20:28.571120 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: LogGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:28.571683 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=3.181125
I20260812 06:20:28.601800 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.030s	user 0.016s	sys 0.012s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":7702,"lbm_writes_lt_1ms":131,"reinsert_count":0,"update_count":640}
I20260812 06:20:28.602430 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.196750
I20260812 06:20:28.615387 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:28.615975 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab): 492 bytes on disk
I20260812 06:20:28.616629 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: UndoDeltaBlockGCOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.617223 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:28.820147 15725 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.763s	user 1.813s	sys 0.138s
I20260812 06:20:28.831048 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.214s	user 0.143s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979834,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16338,"lbm_reads_lt_1ms":771,"lbm_write_time_us":35819,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:20:28.831493 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=14.095187
I20260812 06:20:28.863281 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: FlushDeltaMemStoresOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":15219,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:20:28.863878 15886 maintenance_manager.cc:419] P 5c88e43f06f84678b1d6006c04094eb8: Scheduling MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab): perf score=1.000000
I20260812 06:20:28.905303 15725 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.002s	sys 0.000s
I20260812 06:20:28.905963 15725 tablet_server.cc:179] TabletServer@127.15.91.65:0 shutting down...
I20260812 06:20:28.995376 15826 maintenance_manager.cc:643] P 5c88e43f06f84678b1d6006c04094eb8: MajorDeltaCompactionOp(9a96ebe40c4c4d08b327f10dc70a11ab) complete. Timing: real 0.131s	user 0.121s	sys 0.008s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":439,"lbm_read_time_us":7481,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25590,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2000}
I20260812 06:20:28.996165 15725 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:28.996580 15725 tablet_replica.cc:333] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8: stopping tablet replica
I20260812 06:20:28.996824 15725 raft_consensus.cc:2243] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.997071 15725 raft_consensus.cc:2272] T 9a96ebe40c4c4d08b327f10dc70a11ab P 5c88e43f06f84678b1d6006c04094eb8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.013038 15725 tablet_server.cc:196] TabletServer@127.15.91.65:0 shutdown complete.
I20260812 06:20:29.036064 15725 master.cc:562] Master@127.15.91.126:39581 shutting down...
I20260812 06:20:29.040355 15725 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:29.040560 15725 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.040660 15725 tablet_replica.cc:333] T 00000000000000000000000000000000 P e695dfad257743c18e49220aaa759709: stopping tablet replica
I20260812 06:20:29.053004 15725 master.cc:584] Master@127.15.91.126:39581 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5375 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:29.137559 15725 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.91.126:39443
I20260812 06:20:29.137984 15725 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:29.139946 15916 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:20:29.140095 15725 server_base.cc:1061] running on GCE node
W20260812 06:20:29.140051 15919 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:20:29.140066 15917 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:29.140399 15725 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:29.140465 15725 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:20:29.140492 15725 hybrid_clock.cc:648] HybridClock initialized: now 1786515629140492 us; error 0 us; skew 500 ppm
I20260812 06:20:29.141321 15725 webserver.cc:533] Webserver started at http://127.15.91.126:35039/ using document root <none> and password file <none>
I20260812 06:20:29.141499 15725 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:29.141567 15725 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:29.141647 15725 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:29.142086 15725 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/master-0-root/instance:
uuid: "1f604a12d7a6475a856361970975ba8e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-bxbt"
I20260812 06:20:29.143623 15725 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:29.144687 15924 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:20:29.145031 15725 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:29.145125 15725 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/master-0-root
uuid: "1f604a12d7a6475a856361970975ba8e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-bxbt"
I20260812 06:20:29.145216 15725 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-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:20:29.154843 15725 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:29.155205 15725 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:29.159530 15725 rpc_server.cc:307] RPC server started. Bound to: 127.15.91.126:39443
I20260812 06:20:29.162058 15976 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.91.126:39443 every 8 connection(s)
I20260812 06:20:29.162297 15977 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:20:29.170051 15977 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: Bootstrap starting.
I20260812 06:20:29.173424 15977 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:29.177811 15977 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: No bootstrap required, opened a new log
I20260812 06:20:29.178213 15977 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER }
I20260812 06:20:29.178304 15977 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:29.178326 15977 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1f604a12d7a6475a856361970975ba8e, State: Initialized, Role: FOLLOWER
I20260812 06:20:29.178432 15977 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [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: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER }
I20260812 06:20:29.178488 15977 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:29.178509 15977 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:29.178542 15977 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:29.179243 15977 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER }
I20260812 06:20:29.179359 15977 leader_election.cc:304] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [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: 1f604a12d7a6475a856361970975ba8e; no voters: 
I20260812 06:20:29.179520 15977 leader_election.cc:290] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:29.179711 15980 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:29.179908 15980 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 1 LEADER]: Becoming Leader. State: Replica: 1f604a12d7a6475a856361970975ba8e, State: Running, Role: LEADER
I20260812 06:20:29.180073 15980 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [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: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER }
I20260812 06:20:29.180074 15977 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:29.180579 15981 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1f604a12d7a6475a856361970975ba8e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER } }
I20260812 06:20:29.180625 15982 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1f604a12d7a6475a856361970975ba8e. Latest consensus state: current_term: 1 leader_uuid: "1f604a12d7a6475a856361970975ba8e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f604a12d7a6475a856361970975ba8e" member_type: VOTER } }
I20260812 06:20:29.180744 15981 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:29.180830 15982 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:29.181972 15725 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:29.182462 15996 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:29.182523 15996 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:29.182600 15986 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:29.183243 15986 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:29.185086 15986 catalog_manager.cc:1383] Generated new cluster ID: cdfad7db52fb41c3a624067a7cb33c64
I20260812 06:20:29.185150 15986 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:29.202178 15986 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:29.202853 15986 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:29.213573 15986 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: Generated new TSK 0
I20260812 06:20:29.213799 15986 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:29.246649 15725 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:29.248632 15999 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:20:29.248744 15998 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:20:29.248764 16001 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:20:29.248911 15725 server_base.cc:1061] running on GCE node
I20260812 06:20:29.249135 15725 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:29.249174 15725 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:20:29.249190 15725 hybrid_clock.cc:648] HybridClock initialized: now 1786515629249191 us; error 0 us; skew 500 ppm
I20260812 06:20:29.249989 15725 webserver.cc:533] Webserver started at http://127.15.91.65:45419/ using document root <none> and password file <none>
I20260812 06:20:29.250128 15725 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:29.250171 15725 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:29.250227 15725 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:29.250595 15725 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/instance:
uuid: "b9f74a676fc74a1184eb94e4b504d14e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-bxbt"
I20260812 06:20:29.252166 15725 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:29.253072 16006 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:20:29.253332 15725 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:20:29.253422 15725 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root
uuid: "b9f74a676fc74a1184eb94e4b504d14e"
format_stamp: "Formatted at 2026-08-12 06:20:29 on dist-test-slave-bxbt"
I20260812 06:20:29.253515 15725 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-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:20:29.277380 15725 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:29.277822 15725 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:29.278178 15725 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:29.278690 15725 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:29.278756 15725 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:29.278818 15725 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:29.278872 15725 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:29.283764 15725 rpc_server.cc:307] RPC server started. Bound to: 127.15.91.65:44509
I20260812 06:20:29.283802 16069 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.91.65:44509 every 8 connection(s)
I20260812 06:20:29.293429 16070 heartbeater.cc:344] Connected to a master server at 127.15.91.126:39443
I20260812 06:20:29.293551 16070 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:29.293751 16070 heartbeater.cc:507] Master 127.15.91.126:39443 requested a full tablet report, sending...
I20260812 06:20:29.294351 15941 ts_manager.cc:194] Registered new tserver with Master: b9f74a676fc74a1184eb94e4b504d14e (127.15.91.65:44509)
I20260812 06:20:29.295110 15941 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45298
I20260812 06:20:29.295267 15725 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011038232s
I20260812 06:20:29.302390 15941 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45302:
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:20:29.311233 16034 tablet_service.cc:1511] Processing CreateTablet for tablet 24d83252f9b14ff49e9eea97906b9342 (DEFAULT_TABLE table=heavy-update-compaction-test [id=870c265dba6040dbb2b26978c150c87d]), partition=
I20260812 06:20:29.311514 16034 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 24d83252f9b14ff49e9eea97906b9342. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:29.313668 16082 tablet_bootstrap.cc:492] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Bootstrap starting.
I20260812 06:20:29.314579 16082 tablet_bootstrap.cc:654] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:29.315667 16082 tablet_bootstrap.cc:492] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: No bootstrap required, opened a new log
I20260812 06:20:29.315872 16082 ts_tablet_manager.cc:1403] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:29.316457 16082 raft_consensus.cc:359] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f74a676fc74a1184eb94e4b504d14e" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44509 } }
I20260812 06:20:29.316589 16082 raft_consensus.cc:385] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:29.316672 16082 raft_consensus.cc:740] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b9f74a676fc74a1184eb94e4b504d14e, State: Initialized, Role: FOLLOWER
I20260812 06:20:29.316871 16082 consensus_queue.cc:260] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [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: "b9f74a676fc74a1184eb94e4b504d14e" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44509 } }
I20260812 06:20:29.316989 16082 raft_consensus.cc:399] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:29.317042 16082 raft_consensus.cc:493] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:29.317106 16082 raft_consensus.cc:3060] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:29.317844 16082 raft_consensus.cc:515] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f74a676fc74a1184eb94e4b504d14e" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44509 } }
I20260812 06:20:29.318005 16082 leader_election.cc:304] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [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: b9f74a676fc74a1184eb94e4b504d14e; no voters: 
I20260812 06:20:29.318235 16082 leader_election.cc:290] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:29.318372 16084 raft_consensus.cc:2804] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:29.318593 16082 ts_tablet_manager.cc:1434] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:29.318627 16070 heartbeater.cc:499] Master 127.15.91.126:39443 was elected leader, sending a full tablet report...
I20260812 06:20:29.318603 16084 raft_consensus.cc:697] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 1 LEADER]: Becoming Leader. State: Replica: b9f74a676fc74a1184eb94e4b504d14e, State: Running, Role: LEADER
I20260812 06:20:29.318847 16084 consensus_queue.cc:237] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [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: "b9f74a676fc74a1184eb94e4b504d14e" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44509 } }
I20260812 06:20:29.320339 15941 catalog_manager.cc:5719] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e reported cstate change: term changed from 0 to 1, leader changed from <none> to b9f74a676fc74a1184eb94e4b504d14e (127.15.91.65). New cstate: current_term: 1 leader_uuid: "b9f74a676fc74a1184eb94e4b504d14e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b9f74a676fc74a1184eb94e4b504d14e" member_type: VOTER last_known_addr { host: "127.15.91.65" port: 44509 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:29.378414 15725 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.012s	sys 0.010s
I20260812 06:20:29.534837 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushMRSOp(24d83252f9b14ff49e9eea97906b9342): perf score=19.054940
I20260812 06:20:29.697940 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushMRSOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.163s	user 0.132s	sys 0.028s Metrics: {"bytes_written":12717734,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":847,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42932,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1550}
I20260812 06:20:29.698557 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling LogGCOp(24d83252f9b14ff49e9eea97906b9342): free 20743880 bytes of WAL
I20260812 06:20:29.698792 16011 log_reader.cc:385] T 24d83252f9b14ff49e9eea97906b9342: removed 2 log segments from log reader
I20260812 06:20:29.698855 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000001 (ops 1-6)
I20260812 06:20:29.698908 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000002 (ops 7-11)
I20260812 06:20:29.703701 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: LogGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:29.704105 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:29.729524 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.025s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5189,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.730015 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342): 16411393 bytes on disk
I20260812 06:20:29.730417 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.730813 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:29.749578 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.750233 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:29.955191 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.205s	user 0.137s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":538,"lbm_read_time_us":12374,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33345,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":346,"threads_started":5,"update_count":2500}
I20260812 06:20:29.955981 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:30.005548 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.049s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.006072 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.016810 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.017417 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:30.196714 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.179s	user 0.132s	sys 0.042s 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":265,"lbm_read_time_us":10527,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29844,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:20:30.197482 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:30.245033 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.047s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18799,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.245537 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.256934 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.258121 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:30.415994 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.158s	user 0.114s	sys 0.036s 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":902,"lbm_read_time_us":10530,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29456,"lbm_writes_lt_1ms":543,"mutex_wait_us":325,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:20:30.416659 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:30.462806 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.046s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18635,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.463400 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.479120 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.479867 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:30.634672 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.155s	user 0.107s	sys 0.045s 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":821,"lbm_read_time_us":10023,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32499,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":40064,"update_count":2500}
I20260812 06:20:30.635231 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=11.118625
I20260812 06:20:30.668685 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.033s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15136,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:30.669296 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.695410 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:30.695976 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.706524 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4040,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.707010 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:30.863647 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.156s	user 0.140s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":211,"lbm_read_time_us":10598,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29362,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:20:30.864382 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=10.126437
I20260812 06:20:30.912914 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.048s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23030,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:30.913384 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:30.925078 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.925525 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushMRSOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:30.956498 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushMRSOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1225,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:30.957094 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling LogGCOp(24d83252f9b14ff49e9eea97906b9342): free 112692364 bytes of WAL
I20260812 06:20:30.957320 16011 log_reader.cc:385] T 24d83252f9b14ff49e9eea97906b9342: removed 11 log segments from log reader
I20260812 06:20:30.957363 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000003 (ops 12-16)
I20260812 06:20:30.957420 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000004 (ops 17-21)
I20260812 06:20:30.957464 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000005 (ops 22-26)
I20260812 06:20:30.957521 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000006 (ops 27-31)
I20260812 06:20:30.957561 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000007 (ops 32-36)
I20260812 06:20:30.957610 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000008 (ops 37-41)
I20260812 06:20:30.957646 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000009 (ops 42-46)
I20260812 06:20:30.957700 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000010 (ops 47-51)
I20260812 06:20:30.957741 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000011 (ops 52-56)
I20260812 06:20:30.957778 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000012 (ops 57-61)
I20260812 06:20:30.957816 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000013 (ops 62-66)
I20260812 06:20:30.978966 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: LogGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:20:30.979588 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=3.181125
I20260812 06:20:31.000293 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.020s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7053,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:31.000828 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling LogGCOp(24d83252f9b14ff49e9eea97906b9342): free 11564875 bytes of WAL
I20260812 06:20:31.001075 16011 log_reader.cc:385] T 24d83252f9b14ff49e9eea97906b9342: removed 1 log segments from log reader
I20260812 06:20:31.001147 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000014 (ops 67-70)
I20260812 06:20:31.003340 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: LogGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:31.003732 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:31.015339 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.015988 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:31.231889 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.216s	user 0.162s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":800,"lbm_read_time_us":13620,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40267,"lbm_writes_lt_1ms":643,"mutex_wait_us":76,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":117,"threads_started":1,"update_count":3000}
I20260812 06:20:31.232630 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342): 463 bytes on disk
I20260812 06:20:31.233134 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.233798 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:31.284572 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.051s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18461,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.285131 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:31.301128 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.301734 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:31.467849 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.166s	user 0.118s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":508,"lbm_read_time_us":10320,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28728,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:31.468457 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:31.527961 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.059s	user 0.045s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25973,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.528430 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:31.678756 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.150s	user 0.087s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":576,"lbm_read_time_us":9163,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24151,"lbm_writes_lt_1ms":443,"mutex_wait_us":249,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.679261 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:31.731343 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.052s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21346,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.731932 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:31.743394 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.743875 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:31.938040 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.194s	user 0.142s	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":487,"lbm_read_time_us":10865,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32311,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:31.938521 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:31.990520 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.052s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22368,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.991017 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:32.003568 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.004230 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:32.147573 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.143s	user 0.114s	sys 0.024s 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":517,"lbm_read_time_us":10352,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27097,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:20:32.148259 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=11.118625
I20260812 06:20:32.185309 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.037s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15880,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:32.185842 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:32.201422 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.201992 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:32.326481 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.124s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":7171,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25547,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:32.327171 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=10.126437
I20260812 06:20:32.373415 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.045s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16407,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:32.373989 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:32.385493 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.386161 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushMRSOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:32.414213 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushMRSOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.028s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":171,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1452,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:32.414997 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling LogGCOp(24d83252f9b14ff49e9eea97906b9342): free 112692366 bytes of WAL
I20260812 06:20:32.415294 16011 log_reader.cc:385] T 24d83252f9b14ff49e9eea97906b9342: removed 11 log segments from log reader
I20260812 06:20:32.415374 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000015 (ops 71-75)
I20260812 06:20:32.415428 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000016 (ops 76-80)
I20260812 06:20:32.415467 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000017 (ops 81-85)
I20260812 06:20:32.415510 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000018 (ops 86-90)
I20260812 06:20:32.415551 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000019 (ops 91-95)
I20260812 06:20:32.415593 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000020 (ops 96-100)
I20260812 06:20:32.415633 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000021 (ops 101-105)
I20260812 06:20:32.415694 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000022 (ops 106-110)
I20260812 06:20:32.415735 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000023 (ops 111-115)
I20260812 06:20:32.415774 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000024 (ops 116-120)
I20260812 06:20:32.415810 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000025 (ops 121-125)
I20260812 06:20:32.439168 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: LogGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.024s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:20:32.439603 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=3.181125
I20260812 06:20:32.462102 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.022s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7315,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:32.462618 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342): 462 bytes on disk
I20260812 06:20:32.463091 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:20:32.463649 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:32.474831 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.475456 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:32.663882 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.188s	user 0.137s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1927,"lbm_read_time_us":12248,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39090,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16000,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:32.664626 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:32.719384 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.055s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22005,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.719913 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:32.730901 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.731395 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:32.879293 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.148s	user 0.119s	sys 0.028s 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":347,"lbm_read_time_us":11589,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27771,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:20:32.880119 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=12.110812
I20260812 06:20:32.923877 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.044s	user 0.024s	sys 0.019s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":19397,"lbm_writes_lt_1ms":334,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1655}
I20260812 06:20:32.924497 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.196750
I20260812 06:20:32.937439 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:32.937915 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:33.086496 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.148s	user 0.106s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":9508,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24592,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:20:33.087239 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=11.118625
I20260812 06:20:33.122247 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15826,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:33.122979 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:33.145840 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.023s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:33.146299 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:33.167160 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.167901 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:33.368593 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.200s	user 0.116s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":408,"lbm_read_time_us":14258,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31349,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2500}
I20260812 06:20:33.369372 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:33.428956 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.059s	user 0.034s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29485,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.429481 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:33.442799 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.443367 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:33.636760 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.193s	user 0.117s	sys 0.071s 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":288,"lbm_read_time_us":11652,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33507,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60416,"update_count":2500}
I20260812 06:20:33.637437 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:33.687829 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.050s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":23237,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.688347 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:33.701238 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.701769 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:33.862684 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.161s	user 0.104s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":9257,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30888,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:20:33.863416 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=14.095187
I20260812 06:20:33.912699 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.049s	user 0.029s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22435,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.913221 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=2.188937
I20260812 06:20:33.929375 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.930112 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushMRSOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:33.956665 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushMRSOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1261,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1475,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:33.957659 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling LogGCOp(24d83252f9b14ff49e9eea97906b9342): free 133024588 bytes of WAL
I20260812 06:20:33.958011 16011 log_reader.cc:385] T 24d83252f9b14ff49e9eea97906b9342: removed 13 log segments from log reader
I20260812 06:20:33.958092 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000026 (ops 126-130)
I20260812 06:20:33.958148 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000027 (ops 131-134)
I20260812 06:20:33.958206 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000028 (ops 135-139)
I20260812 06:20:33.958254 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000029 (ops 140-144)
I20260812 06:20:33.958292 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000030 (ops 145-149)
I20260812 06:20:33.958334 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000031 (ops 150-154)
I20260812 06:20:33.958371 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000032 (ops 155-159)
I20260812 06:20:33.958410 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000033 (ops 160-164)
I20260812 06:20:33.958447 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000034 (ops 165-169)
I20260812 06:20:33.958483 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000035 (ops 170-174)
I20260812 06:20:33.958521 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000036 (ops 175-179)
I20260812 06:20:33.958559 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000037 (ops 180-184)
I20260812 06:20:33.958595 16011 log.cc:1079] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: Deleting log segment in path: /tmp/dist-test-task11UzF1/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515623751335-15725-0/minicluster-data/ts-0-root/wals/24d83252f9b14ff49e9eea97906b9342/wal-000000038 (ops 185-189)
I20260812 06:20:33.986274 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: LogGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:33.986819 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=5.165500
I20260812 06:20:34.014611 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.027s	user 0.012s	sys 0.012s Metrics: {"bytes_written":7343569,"delete_count":0,"lbm_write_time_us":7727,"lbm_writes_lt_1ms":182,"reinsert_count":0,"update_count":895}
I20260812 06:20:34.015208 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342): 482 bytes on disk
I20260812 06:20:34.015756 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: UndoDeltaBlockGCOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:20:34.016321 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342): perf score=1.000000
I20260812 06:20:34.242606 15725 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.864s	user 1.802s	sys 0.162s
I20260812 06:20:34.246577 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: MajorDeltaCompactionOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.230s	user 0.142s	sys 0.075s Metrics: {"cfile_cache_miss":712,"cfile_cache_miss_bytes":32118122,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3252,"lbm_read_time_us":15786,"lbm_reads_lt_1ms":748,"lbm_write_time_us":38500,"lbm_writes_lt_1ms":722,"mutex_wait_us":1431,"peak_mem_usage":85026541,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":78,"threads_started":1,"update_count":3395}
I20260812 06:20:34.247098 16071 maintenance_manager.cc:419] P b9f74a676fc74a1184eb94e4b504d14e: Scheduling FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342): perf score=19.056125
I20260812 06:20:34.274549 15725 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.002s	sys 0.000s
I20260812 06:20:34.275203 15725 tablet_server.cc:179] TabletServer@127.15.91.65:0 shutting down...
I20260812 06:20:34.329485 16011 maintenance_manager.cc:643] P b9f74a676fc74a1184eb94e4b504d14e: FlushDeltaMemStoresOp(24d83252f9b14ff49e9eea97906b9342) complete. Timing: real 0.082s	user 0.049s	sys 0.031s Metrics: {"bytes_written":21373825,"delete_count":0,"lbm_write_time_us":33187,"lbm_writes_lt_1ms":524,"reinsert_count":0,"update_count":2605}
I20260812 06:20:34.330077 15725 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:34.330317 15725 tablet_replica.cc:333] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e: stopping tablet replica
I20260812 06:20:34.330492 15725 raft_consensus.cc:2243] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:34.330698 15725 raft_consensus.cc:2272] T 24d83252f9b14ff49e9eea97906b9342 P b9f74a676fc74a1184eb94e4b504d14e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:34.334358 15725 tablet_server.cc:196] TabletServer@127.15.91.65:0 shutdown complete.
I20260812 06:20:34.337204 15725 master.cc:562] Master@127.15.91.126:39443 shutting down...
I20260812 06:20:34.340576 15725 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:34.340751 15725 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:34.340844 15725 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1f604a12d7a6475a856361970975ba8e: stopping tablet replica
I20260812 06:20:34.353176 15725 master.cc:584] Master@127.15.91.126:39443 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5299 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10675 ms total)

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