[==========] 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:18.996204 24420 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.217.62:46607
I20260812 06:20:18.997232 24420 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:18.997835 24420 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:19.004617 24420 server_base.cc:1061] running on GCE node
W20260812 06:20:19.004770 24431 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:19.004810 24433 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:19.004830 24435 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:19.005402 24420 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:19.005504 24420 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:19.005579 24420 hybrid_clock.cc:648] HybridClock initialized: now 1786515619005576 us; error 0 us; skew 500 ppm
I20260812 06:20:19.007508 24420 webserver.cc:533] Webserver started at http://127.23.217.62:40733/ using document root <none> and password file <none>
I20260812 06:20:19.008082 24420 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:19.008154 24420 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:19.008406 24420 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:19.010078 24420 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/master-0-root/instance:
uuid: "06f6a0cf6d114916bd4004477c3821a6"
format_stamp: "Formatted at 2026-08-12 06:20:19 on dist-test-slave-pww0"
I20260812 06:20:19.013604 24420 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.004s
I20260812 06:20:19.015714 24444 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:19.016713 24420 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:19.016815 24420 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/master-0-root
uuid: "06f6a0cf6d114916bd4004477c3821a6"
format_stamp: "Formatted at 2026-08-12 06:20:19 on dist-test-slave-pww0"
I20260812 06:20:19.016909 24420 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-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:19.044684 24420 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:19.045377 24420 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:19.045542 24420 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:19.053385 24420 rpc_server.cc:307] RPC server started. Bound to: 127.23.217.62:46607
I20260812 06:20:19.053462 24540 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.217.62:46607 every 8 connection(s)
I20260812 06:20:19.055783 24541 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:19.061477 24541 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: Bootstrap starting.
I20260812 06:20:19.063930 24541 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:19.064873 24541 log.cc:826] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:19.066671 24541 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: No bootstrap required, opened a new log
I20260812 06:20:19.069646 24541 raft_consensus.cc:359] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER }
I20260812 06:20:19.069856 24541 raft_consensus.cc:385] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:19.069932 24541 raft_consensus.cc:740] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 06f6a0cf6d114916bd4004477c3821a6, State: Initialized, Role: FOLLOWER
I20260812 06:20:19.070580 24541 consensus_queue.cc:260] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [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: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER }
I20260812 06:20:19.070829 24548 raft_consensus.cc:493] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Starting pre-election (no leader contacted us within the election timeout)
I20260812 06:20:19.071009 24548 raft_consensus.cc:515] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Starting pre-election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER }
I20260812 06:20:19.070779 24541 raft_consensus.cc:399] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:19.071532 24548 leader_election.cc:304] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [CANDIDATE]: Term 1 pre-election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 06f6a0cf6d114916bd4004477c3821a6; no voters: 
I20260812 06:20:19.071607 24541 raft_consensus.cc:493] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:19.071692 24541 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:19.071918 24548 leader_election.cc:290] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [CANDIDATE]: Term 1 pre-election: Requested pre-vote from peers 
I20260812 06:20:19.072602 24541 raft_consensus.cc:515] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER }
I20260812 06:20:19.072731 24541 leader_election.cc:304] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [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: 06f6a0cf6d114916bd4004477c3821a6; no voters: 
I20260812 06:20:19.072780 24549 raft_consensus.cc:2764] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 FOLLOWER]: Leader pre-election decision vote started in defunct term 0: won
I20260812 06:20:19.072824 24541 leader_election.cc:290] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:19.073187 24548 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:19.073171 24550 sys_catalog.cc:455] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER } }
I20260812 06:20:19.073300 24548 raft_consensus.cc:697] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 LEADER]: Becoming Leader. State: Replica: 06f6a0cf6d114916bd4004477c3821a6, State: Running, Role: LEADER
I20260812 06:20:19.073308 24550 sys_catalog.cc:458] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [sys.catalog]: This master's current role is: FOLLOWER
I20260812 06:20:19.073700 24548 consensus_queue.cc:237] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [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: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER }
I20260812 06:20:19.073817 24541 sys_catalog.cc:565] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:19.075353 24549 sys_catalog.cc:455] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 06f6a0cf6d114916bd4004477c3821a6. Latest consensus state: current_term: 1 leader_uuid: "06f6a0cf6d114916bd4004477c3821a6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06f6a0cf6d114916bd4004477c3821a6" member_type: VOTER } }
I20260812 06:20:19.075433 24549 sys_catalog.cc:458] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:19.075803 24565 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:19.076049 24420 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:19.078198 24565 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:19.082844 24565 catalog_manager.cc:1383] Generated new cluster ID: c6721c16aa324e87b66c02a75d28e639
I20260812 06:20:19.082923 24565 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:19.094340 24565 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:19.095219 24565 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:19.104060 24565 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: Generated new TSK 0
I20260812 06:20:19.104717 24565 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:19.108527 24420 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:19.111078 24593 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:19.111191 24420 server_base.cc:1061] running on GCE node
W20260812 06:20:19.111096 24592 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:19.111243 24596 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:19.111570 24420 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:19.111626 24420 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:19.111649 24420 hybrid_clock.cc:648] HybridClock initialized: now 1786515619111649 us; error 0 us; skew 500 ppm
I20260812 06:20:19.112610 24420 webserver.cc:533] Webserver started at http://127.23.217.1:43449/ using document root <none> and password file <none>
I20260812 06:20:19.112782 24420 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:19.112844 24420 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:19.112921 24420 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:19.113373 24420 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/instance:
uuid: "07606a50041c453ba753c818e59841f4"
format_stamp: "Formatted at 2026-08-12 06:20:19 on dist-test-slave-pww0"
I20260812 06:20:19.115214 24420 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:19.116418 24602 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:19.116671 24420 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:19.116737 24420 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root
uuid: "07606a50041c453ba753c818e59841f4"
format_stamp: "Formatted at 2026-08-12 06:20:19 on dist-test-slave-pww0"
I20260812 06:20:19.116811 24420 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-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:19.141604 24420 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:19.142234 24420 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:19.142813 24420 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:19.143784 24420 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:19.143843 24420 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:19.143904 24420 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:19.143939 24420 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:19.150225 24420 rpc_server.cc:307] RPC server started. Bound to: 127.23.217.1:33683
I20260812 06:20:19.150254 24728 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.217.1:33683 every 8 connection(s)
I20260812 06:20:19.161921 24730 heartbeater.cc:344] Connected to a master server at 127.23.217.62:46607
I20260812 06:20:19.162236 24730 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:19.162801 24730 heartbeater.cc:507] Master 127.23.217.62:46607 requested a full tablet report, sending...
I20260812 06:20:19.164438 24478 ts_manager.cc:194] Registered new tserver with Master: 07606a50041c453ba753c818e59841f4 (127.23.217.1:33683)
I20260812 06:20:19.164494 24420 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013590361s
I20260812 06:20:19.166020 24478 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56582
I20260812 06:20:19.174180 24478 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56588:
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:19.188906 24653 tablet_service.cc:1511] Processing CreateTablet for tablet f976784fe25a4636b66131306d69e500 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1c9722ba224d47e8803ea162db8d3d72]), partition=
I20260812 06:20:19.189379 24653 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f976784fe25a4636b66131306d69e500. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:19.191815 24750 tablet_bootstrap.cc:492] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Bootstrap starting.
I20260812 06:20:19.192720 24750 tablet_bootstrap.cc:654] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:19.193817 24750 tablet_bootstrap.cc:492] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: No bootstrap required, opened a new log
I20260812 06:20:19.193920 24750 ts_tablet_manager.cc:1403] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:19.194361 24750 raft_consensus.cc:359] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07606a50041c453ba753c818e59841f4" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 33683 } }
I20260812 06:20:19.194468 24750 raft_consensus.cc:385] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:19.194491 24750 raft_consensus.cc:740] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 07606a50041c453ba753c818e59841f4, State: Initialized, Role: FOLLOWER
I20260812 06:20:19.194626 24750 consensus_queue.cc:260] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [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: "07606a50041c453ba753c818e59841f4" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 33683 } }
I20260812 06:20:19.194711 24750 raft_consensus.cc:399] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:19.194751 24750 raft_consensus.cc:493] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:19.194800 24750 raft_consensus.cc:3060] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:19.196033 24750 raft_consensus.cc:515] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07606a50041c453ba753c818e59841f4" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 33683 } }
I20260812 06:20:19.196197 24750 leader_election.cc:304] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [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: 07606a50041c453ba753c818e59841f4; no voters: 
I20260812 06:20:19.196424 24750 leader_election.cc:290] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:19.196558 24758 raft_consensus.cc:2804] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:19.196794 24758 raft_consensus.cc:697] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 1 LEADER]: Becoming Leader. State: Replica: 07606a50041c453ba753c818e59841f4, State: Running, Role: LEADER
I20260812 06:20:19.196825 24750 ts_tablet_manager.cc:1434] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:19.197007 24758 consensus_queue.cc:237] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [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: "07606a50041c453ba753c818e59841f4" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 33683 } }
I20260812 06:20:19.197060 24730 heartbeater.cc:499] Master 127.23.217.62:46607 was elected leader, sending a full tablet report...
I20260812 06:20:19.199957 24478 catalog_manager.cc:5719] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 07606a50041c453ba753c818e59841f4 (127.23.217.1). New cstate: current_term: 1 leader_uuid: "07606a50041c453ba753c818e59841f4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07606a50041c453ba753c818e59841f4" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 33683 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:19.272117 24420 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.033s	sys 0.001s
I20260812 06:20:19.401433 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushMRSOp(f976784fe25a4636b66131306d69e500): perf score=19.054940
I20260812 06:20:19.574988 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushMRSOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.173s	user 0.128s	sys 0.044s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":202,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":826,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42024,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":363264,"thread_start_us":119,"threads_started":1,"update_count":1550}
I20260812 06:20:19.576522 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling LogGCOp(f976784fe25a4636b66131306d69e500): free 20743880 bytes of WAL
I20260812 06:20:19.576874 24612 log_reader.cc:385] T f976784fe25a4636b66131306d69e500: removed 2 log segments from log reader
I20260812 06:20:19.579311 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000001 (ops 1-6)
I20260812 06:20:19.579562 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000002 (ops 7-11)
I20260812 06:20:19.584528 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: LogGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.008s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:20:19.584980 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500): 16411395 bytes on disk
I20260812 06:20:19.585642 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.586107 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:19.606174 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.606741 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:19.620662 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:19.621201 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:19.782040 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.161s	user 0.119s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":494,"lbm_read_time_us":10690,"lbm_reads_lt_1ms":569,"lbm_write_time_us":26567,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":312,"threads_started":5,"update_count":2500}
I20260812 06:20:19.782625 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:19.825635 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.043s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.826176 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:19.841620 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.842227 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:19.970892 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.128s	user 0.078s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1115,"lbm_read_time_us":8235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24861,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:20:19.971670 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:20.012508 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.041s	user 0.026s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16051,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.013070 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:20.023916 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.024551 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.150020 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.125s	user 0.108s	sys 0.017s 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":589,"lbm_read_time_us":7628,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23144,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:20:20.150653 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:20.196576 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.046s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16829,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.197109 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:20.208024 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.208657 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.330214 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.121s	user 0.090s	sys 0.031s 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":187,"lbm_read_time_us":8433,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23551,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":79872,"update_count":2000}
I20260812 06:20:20.330762 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:20.376313 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.045s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.376895 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:20.387421 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.387956 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.529394 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.141s	user 0.104s	sys 0.037s 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":215,"lbm_read_time_us":10288,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21714,"lbm_writes_lt_1ms":443,"mutex_wait_us":112,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":62464,"update_count":2000}
I20260812 06:20:20.529917 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:20.568663 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16818,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:20:20.569247 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.670742 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.101s	user 0.081s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1088,"lbm_read_time_us":5719,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18094,"lbm_writes_lt_1ms":343,"mutex_wait_us":62,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":1500}
I20260812 06:20:20.671325 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:20.705693 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.034s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14164,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.706323 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushMRSOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.743330 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushMRSOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.037s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1410,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1632,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:20.744452 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling LogGCOp(f976784fe25a4636b66131306d69e500): free 103925248 bytes of WAL
I20260812 06:20:20.744840 24612 log_reader.cc:385] T f976784fe25a4636b66131306d69e500: removed 10 log segments from log reader
I20260812 06:20:20.744899 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000003 (ops 12-16)
I20260812 06:20:20.744940 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000004 (ops 17-21)
I20260812 06:20:20.744975 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000005 (ops 22-26)
I20260812 06:20:20.745007 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000006 (ops 27-31)
I20260812 06:20:20.745033 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000007 (ops 32-36)
I20260812 06:20:20.745060 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000008 (ops 37-41)
I20260812 06:20:20.745090 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000009 (ops 42-46)
I20260812 06:20:20.745121 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000010 (ops 47-51)
I20260812 06:20:20.745151 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000011 (ops 52-56)
I20260812 06:20:20.745182 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000012 (ops 57-61)
I20260812 06:20:20.760350 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: LogGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.016s	user 0.000s	sys 0.015s Metrics: {}
I20260812 06:20:20.760866 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500): 447 bytes on disk
I20260812 06:20:20.761445 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:20:20.761914 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=6.157687
I20260812 06:20:20.781831 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8106,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:20.782251 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling LogGCOp(f976784fe25a4636b66131306d69e500): free 8767123 bytes of WAL
I20260812 06:20:20.782433 24612 log_reader.cc:385] T f976784fe25a4636b66131306d69e500: removed 1 log segments from log reader
I20260812 06:20:20.782471 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000013 (ops 62-66)
I20260812 06:20:20.783879 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: LogGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:20.784180 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:20.935812 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.151s	user 0.097s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1614,"lbm_read_time_us":9259,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29954,"lbm_writes_lt_1ms":543,"mutex_wait_us":1040,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":118,"threads_started":1,"update_count":2500}
I20260812 06:20:20.936369 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=11.118625
I20260812 06:20:20.968472 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":13456166,"delete_count":0,"lbm_write_time_us":12896,"lbm_writes_lt_1ms":331,"mutex_wait_us":945,"reinsert_count":0,"update_count":1640}
I20260812 06:20:20.968959 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=1.196750
I20260812 06:20:20.978132 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3134,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:20.978801 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:21.121541 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.143s	user 0.098s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":390,"lbm_read_time_us":8957,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23991,"lbm_writes_lt_1ms":443,"mutex_wait_us":102,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:20:21.122192 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=11.118625
I20260812 06:20:21.170674 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19920,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.171195 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:21.188011 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.188479 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:21.203811 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.015s	user 0.000s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3426,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.204340 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:21.374910 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.170s	user 0.097s	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":134,"lbm_read_time_us":12101,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28502,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:21.375588 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:21.406579 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.031s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12312,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.407058 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:21.418061 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.418622 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:21.543967 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.125s	user 0.105s	sys 0.019s 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":180,"lbm_read_time_us":7664,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26051,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:20:21.544456 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:21.592243 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.048s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.592859 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:21.603029 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.603711 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:21.719732 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.116s	user 0.103s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":9264,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20681,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:20:21.720511 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:21.753886 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.033s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12747,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.754441 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:21.852771 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.098s	user 0.082s	sys 0.016s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":255,"lbm_read_time_us":6432,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17893,"lbm_writes_lt_1ms":343,"mutex_wait_us":35,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":1500}
I20260812 06:20:21.853405 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:21.898232 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.045s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16155,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:21.898869 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:21.909232 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.910835 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.034672 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.124s	user 0.087s	sys 0.034s 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":579,"lbm_read_time_us":7593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23412,"lbm_writes_lt_1ms":443,"mutex_wait_us":272,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.035203 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:22.078527 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.043s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13037,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.079048 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.090224 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.091001 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushMRSOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.118667 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushMRSOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1711,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:22.119601 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling LogGCOp(f976784fe25a4636b66131306d69e500): free 123804199 bytes of WAL
I20260812 06:20:22.119863 24612 log_reader.cc:385] T f976784fe25a4636b66131306d69e500: removed 12 log segments from log reader
I20260812 06:20:22.119916 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000014 (ops 67-70)
I20260812 06:20:22.119963 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000015 (ops 71-75)
I20260812 06:20:22.119995 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000016 (ops 76-80)
I20260812 06:20:22.120020 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000017 (ops 81-84)
I20260812 06:20:22.120051 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000018 (ops 85-89)
I20260812 06:20:22.120083 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000019 (ops 90-94)
I20260812 06:20:22.120116 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000020 (ops 95-99)
I20260812 06:20:22.120144 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000021 (ops 100-104)
I20260812 06:20:22.120172 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000022 (ops 105-109)
I20260812 06:20:22.120200 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000023 (ops 110-114)
I20260812 06:20:22.120229 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000024 (ops 115-119)
I20260812 06:20:22.120260 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000025 (ops 120-124)
I20260812 06:20:22.142395 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: LogGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:20:22.142835 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.158624 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.159121 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500): 462 bytes on disk
I20260812 06:20:22.159644 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.160203 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.170634 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.171325 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.337464 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.166s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":940,"lbm_read_time_us":11195,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32720,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":37760,"thread_start_us":165,"threads_started":1,"update_count":3000}
I20260812 06:20:22.338138 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=11.118625
I20260812 06:20:22.372433 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.034s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13927,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:22.372937 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.385185 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.385808 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.501713 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.116s	user 0.103s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":6741,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21737,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:20:22.502341 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:22.541476 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.541989 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.552299 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.553148 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.674785 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.121s	user 0.101s	sys 0.017s 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":148,"lbm_read_time_us":8355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20571,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:20:22.675374 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:22.727417 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.052s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14989,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.727999 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.738584 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.006s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.739068 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:22.882974 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.144s	user 0.111s	sys 0.032s 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":971,"lbm_read_time_us":9321,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24088,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":2000}
I20260812 06:20:22.883632 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:22.922282 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.038s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17025,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.922770 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:22.934376 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.934918 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.056670 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.121s	user 0.108s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":740,"lbm_read_time_us":7557,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24197,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.057375 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:23.121126 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.063s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":37488,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.121737 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:23.134828 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.135497 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.252629 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.117s	user 0.088s	sys 0.029s 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":921,"lbm_read_time_us":7777,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23047,"lbm_writes_lt_1ms":443,"mutex_wait_us":257,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:20:23.253225 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:23.307137 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.054s	user 0.023s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19115,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.307696 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:23.318475 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.318970 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.457535 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.138s	user 0.102s	sys 0.036s 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":153,"lbm_read_time_us":9582,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23294,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.460765 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=10.126437
I20260812 06:20:23.504676 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.044s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15008,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.505213 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:23.517405 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.518266 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushMRSOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.550611 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushMRSOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1432,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1955,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:23.551414 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling LogGCOp(f976784fe25a4636b66131306d69e500): free 120553618 bytes of WAL
I20260812 06:20:23.551676 24612 log_reader.cc:385] T f976784fe25a4636b66131306d69e500: removed 12 log segments from log reader
I20260812 06:20:23.551724 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000026 (ops 125-129)
I20260812 06:20:23.551789 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000027 (ops 130-134)
I20260812 06:20:23.551820 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000028 (ops 135-139)
I20260812 06:20:23.551846 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000029 (ops 140-144)
I20260812 06:20:23.551877 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000030 (ops 145-149)
I20260812 06:20:23.551906 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000031 (ops 150-154)
I20260812 06:20:23.551936 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000032 (ops 155-158)
I20260812 06:20:23.551966 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000033 (ops 159-163)
I20260812 06:20:23.551996 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000034 (ops 164-168)
I20260812 06:20:23.552026 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000035 (ops 169-173)
I20260812 06:20:23.552057 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000036 (ops 174-178)
I20260812 06:20:23.552086 24612 log.cc:1079] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/f976784fe25a4636b66131306d69e500/wal-000000037 (ops 179-182)
I20260812 06:20:23.573601 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: LogGCOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:20:23.574069 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=3.181125
I20260812 06:20:23.600330 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.026s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6572,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.600917 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:23.610661 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3512,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.611220 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500): 472 bytes on disk
I20260812 06:20:23.611711 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: UndoDeltaBlockGCOp(f976784fe25a4636b66131306d69e500) 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:23.612381 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.803699 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.191s	user 0.118s	sys 0.062s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":600,"lbm_read_time_us":12772,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30786,"lbm_writes_lt_1ms":643,"mutex_wait_us":329,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21888,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:23.804355 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=14.095187
I20260812 06:20:23.859375 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.054s	user 0.010s	sys 0.040s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19550,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.860085 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=2.188937
I20260812 06:20:23.871060 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.871620 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500): perf score=1.000000
I20260812 06:20:23.966006 24420 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.694s	user 1.702s	sys 0.152s
I20260812 06:20:24.035048 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: MajorDeltaCompactionOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.163s	user 0.130s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":12156,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27390,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":57856,"update_count":2500}
I20260812 06:20:24.035662 24731 maintenance_manager.cc:419] P 07606a50041c453ba753c818e59841f4: Scheduling FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500): perf score=6.157687
I20260812 06:20:24.044685 24420 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.002s	sys 0.000s
I20260812 06:20:24.045360 24420 tablet_server.cc:179] TabletServer@127.23.217.1:0 shutting down...
I20260812 06:20:24.057277 24612 maintenance_manager.cc:643] P 07606a50041c453ba753c818e59841f4: FlushDeltaMemStoresOp(f976784fe25a4636b66131306d69e500) complete. Timing: real 0.021s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8604,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:24.057967 24420 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:24.058374 24420 tablet_replica.cc:333] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4: stopping tablet replica
I20260812 06:20:24.058585 24420 raft_consensus.cc:2243] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:24.058781 24420 raft_consensus.cc:2272] T f976784fe25a4636b66131306d69e500 P 07606a50041c453ba753c818e59841f4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:24.073830 24420 tablet_server.cc:196] TabletServer@127.23.217.1:0 shutdown complete.
I20260812 06:20:24.080825 24420 master.cc:562] Master@127.23.217.62:46607 shutting down...
I20260812 06:20:24.084169 24420 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:24.084354 24420 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:24.084434 24420 tablet_replica.cc:333] T 00000000000000000000000000000000 P 06f6a0cf6d114916bd4004477c3821a6: stopping tablet replica
I20260812 06:20:24.096735 24420 master.cc:584] Master@127.23.217.62:46607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5172 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:24.177531 24420 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.217.62:37223
I20260812 06:20:24.178000 24420 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:24.180363 24788 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:24.180397 24420 server_base.cc:1061] running on GCE node
W20260812 06:20:24.180393 24787 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:24.180433 24791 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:24.180716 24420 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:24.180763 24420 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:24.180783 24420 hybrid_clock.cc:648] HybridClock initialized: now 1786515624180782 us; error 0 us; skew 500 ppm
I20260812 06:20:24.181746 24420 webserver.cc:533] Webserver started at http://127.23.217.62:44299/ using document root <none> and password file <none>
I20260812 06:20:24.181923 24420 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:24.181977 24420 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:24.182060 24420 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:24.182461 24420 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/master-0-root/instance:
uuid: "70626035ef424bdb8df0f734e3dc61ee"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-pww0"
I20260812 06:20:24.184309 24420 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:24.185353 24804 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:24.185614 24420 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:24.185701 24420 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/master-0-root
uuid: "70626035ef424bdb8df0f734e3dc61ee"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-pww0"
I20260812 06:20:24.185775 24420 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-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:24.212535 24420 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:24.212970 24420 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:24.217217 24420 rpc_server.cc:307] RPC server started. Bound to: 127.23.217.62:37223
I20260812 06:20:24.220870 24916 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.217.62:37223 every 8 connection(s)
I20260812 06:20:24.221354 24917 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:24.223263 24917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee: Bootstrap starting.
I20260812 06:20:24.224117 24917 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:24.225229 24917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee: No bootstrap required, opened a new log
I20260812 06:20:24.225639 24917 raft_consensus.cc:359] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER }
I20260812 06:20:24.225744 24917 raft_consensus.cc:385] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:24.225775 24917 raft_consensus.cc:740] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 70626035ef424bdb8df0f734e3dc61ee, State: Initialized, Role: FOLLOWER
I20260812 06:20:24.225919 24917 consensus_queue.cc:260] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [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: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER }
I20260812 06:20:24.226007 24917 raft_consensus.cc:399] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:24.226049 24917 raft_consensus.cc:493] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:24.226096 24917 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:24.226850 24917 raft_consensus.cc:515] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER }
I20260812 06:20:24.226981 24917 leader_election.cc:304] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [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: 70626035ef424bdb8df0f734e3dc61ee; no voters: 
I20260812 06:20:24.227190 24917 leader_election.cc:290] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:24.227368 24923 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:24.227596 24923 raft_consensus.cc:697] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 1 LEADER]: Becoming Leader. State: Replica: 70626035ef424bdb8df0f734e3dc61ee, State: Running, Role: LEADER
I20260812 06:20:24.227689 24917 sys_catalog.cc:565] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:24.227741 24923 consensus_queue.cc:237] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [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: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER }
I20260812 06:20:24.228194 24924 sys_catalog.cc:455] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "70626035ef424bdb8df0f734e3dc61ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER } }
I20260812 06:20:24.228212 24925 sys_catalog.cc:455] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader 70626035ef424bdb8df0f734e3dc61ee. Latest consensus state: current_term: 1 leader_uuid: "70626035ef424bdb8df0f734e3dc61ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70626035ef424bdb8df0f734e3dc61ee" member_type: VOTER } }
I20260812 06:20:24.228307 24924 sys_catalog.cc:458] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.228317 24925 sys_catalog.cc:458] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:24.228550 24929 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:24.229532 24929 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:24.229704 24420 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:24.231580 24929 catalog_manager.cc:1383] Generated new cluster ID: 2231c5742dc349338eca8b57bcff73d2
I20260812 06:20:24.231654 24929 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:24.243944 24929 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:24.244539 24929 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:24.257169 24929 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee: Generated new TSK 0
I20260812 06:20:24.257383 24929 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:24.262471 24420 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:24.264530 24949 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:24.264608 24961 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:24.264714 24420 server_base.cc:1061] running on GCE node
W20260812 06:20:24.264614 24953 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:24.264968 24420 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:24.265012 24420 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:24.265026 24420 hybrid_clock.cc:648] HybridClock initialized: now 1786515624265026 us; error 0 us; skew 500 ppm
I20260812 06:20:24.265933 24420 webserver.cc:533] Webserver started at http://127.23.217.1:44087/ using document root <none> and password file <none>
I20260812 06:20:24.266083 24420 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:24.266132 24420 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:24.266193 24420 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:24.266551 24420 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/instance:
uuid: "d21b19661ba04527a8dd0876071d872d"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-pww0"
I20260812 06:20:24.268181 24420 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:24.269095 24968 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:24.269316 24420 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:24.269384 24420 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root
uuid: "d21b19661ba04527a8dd0876071d872d"
format_stamp: "Formatted at 2026-08-12 06:20:24 on dist-test-slave-pww0"
I20260812 06:20:24.269457 24420 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-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:24.281713 24420 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:24.282217 24420 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:24.282629 24420 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:24.283157 24420 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:24.283205 24420 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:24.283252 24420 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:24.283270 24420 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:24.287843 24420 rpc_server.cc:307] RPC server started. Bound to: 127.23.217.1:36071
I20260812 06:20:24.288427 25095 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.217.1:36071 every 8 connection(s)
I20260812 06:20:24.298525 25097 heartbeater.cc:344] Connected to a master server at 127.23.217.62:37223
I20260812 06:20:24.298687 25097 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:24.298949 25097 heartbeater.cc:507] Master 127.23.217.62:37223 requested a full tablet report, sending...
I20260812 06:20:24.299710 24841 ts_manager.cc:194] Registered new tserver with Master: d21b19661ba04527a8dd0876071d872d (127.23.217.1:36071)
I20260812 06:20:24.299779 24420 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011224776s
I20260812 06:20:24.300495 24841 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59860
I20260812 06:20:24.307178 24841 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59870:
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:24.316455 25022 tablet_service.cc:1511] Processing CreateTablet for tablet c0f316603e6b4aa5b6f7816019661a2d (DEFAULT_TABLE table=heavy-update-compaction-test [id=35619d9c57b64e3a9b2896bf9a04147d]), partition=
I20260812 06:20:24.316766 25022 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c0f316603e6b4aa5b6f7816019661a2d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:24.318878 25117 tablet_bootstrap.cc:492] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Bootstrap starting.
I20260812 06:20:24.319800 25117 tablet_bootstrap.cc:654] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:24.320883 25117 tablet_bootstrap.cc:492] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: No bootstrap required, opened a new log
I20260812 06:20:24.320969 25117 ts_tablet_manager.cc:1403] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:24.321357 25117 raft_consensus.cc:359] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d21b19661ba04527a8dd0876071d872d" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 36071 } }
I20260812 06:20:24.321470 25117 raft_consensus.cc:385] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:24.321513 25117 raft_consensus.cc:740] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d21b19661ba04527a8dd0876071d872d, State: Initialized, Role: FOLLOWER
I20260812 06:20:24.321645 25117 consensus_queue.cc:260] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [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: "d21b19661ba04527a8dd0876071d872d" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 36071 } }
I20260812 06:20:24.321741 25117 raft_consensus.cc:399] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:24.321774 25117 raft_consensus.cc:493] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:24.321810 25117 raft_consensus.cc:3060] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:24.322665 25117 raft_consensus.cc:515] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d21b19661ba04527a8dd0876071d872d" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 36071 } }
I20260812 06:20:24.322817 25117 leader_election.cc:304] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [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: d21b19661ba04527a8dd0876071d872d; no voters: 
I20260812 06:20:24.323028 25117 leader_election.cc:290] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:24.323228 25120 raft_consensus.cc:2804] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:24.323395 25117 ts_tablet_manager.cc:1434] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:24.323448 25120 raft_consensus.cc:697] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 1 LEADER]: Becoming Leader. State: Replica: d21b19661ba04527a8dd0876071d872d, State: Running, Role: LEADER
I20260812 06:20:24.323486 25097 heartbeater.cc:499] Master 127.23.217.62:37223 was elected leader, sending a full tablet report...
I20260812 06:20:24.323657 25120 consensus_queue.cc:237] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [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: "d21b19661ba04527a8dd0876071d872d" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 36071 } }
I20260812 06:20:24.325105 24841 catalog_manager.cc:5719] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d reported cstate change: term changed from 0 to 1, leader changed from <none> to d21b19661ba04527a8dd0876071d872d (127.23.217.1). New cstate: current_term: 1 leader_uuid: "d21b19661ba04527a8dd0876071d872d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d21b19661ba04527a8dd0876071d872d" member_type: VOTER last_known_addr { host: "127.23.217.1" port: 36071 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:24.383373 24420 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:20:24.538991 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=19.054940
I20260812 06:20:24.686883 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.148s	user 0.109s	sys 0.035s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":829,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35068,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:20:24.687665 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling LogGCOp(c0f316603e6b4aa5b6f7816019661a2d): free 20743880 bytes of WAL
I20260812 06:20:24.687991 24976 log_reader.cc:385] T c0f316603e6b4aa5b6f7816019661a2d: removed 2 log segments from log reader
I20260812 06:20:24.688074 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000001 (ops 1-6)
I20260812 06:20:24.688117 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000002 (ops 7-11)
I20260812 06:20:24.693270 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: LogGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:24.693742 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:24.704941 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.705498 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:24.861167 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.155s	user 0.122s	sys 0.027s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303020,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":437,"lbm_read_time_us":9885,"lbm_reads_lt_1ms":458,"lbm_write_time_us":21975,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":337,"threads_started":5,"update_count":1950}
I20260812 06:20:24.861888 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d): 16821646 bytes on disk
I20260812 06:20:24.862720 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.863211 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=11.118625
I20260812 06:20:24.893435 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.030s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12195,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.893909 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:24.917958 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.024s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.918568 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:24.933851 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.934528 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.110993 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.176s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":157,"lbm_read_time_us":11992,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24844,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:20:25.111608 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:25.161911 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.050s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20890,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.162457 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:25.173501 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.174161 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.318495 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.144s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":407,"lbm_read_time_us":9337,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28670,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:20:25.319191 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=10.126437
I20260812 06:20:25.358098 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16329,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.358596 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:25.373947 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.374758 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.498103 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.123s	user 0.111s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":900,"lbm_read_time_us":9405,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21601,"lbm_writes_lt_1ms":443,"mutex_wait_us":234,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:20:25.498723 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=10.126437
I20260812 06:20:25.538894 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.040s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15448,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.539538 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:25.549691 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.550362 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.665330 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.115s	user 0.104s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1052,"lbm_read_time_us":7998,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21224,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:25.665999 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=10.126437
I20260812 06:20:25.714936 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.049s	user 0.015s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17355,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.715547 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:25.731667 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.732197 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.874027 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.142s	user 0.090s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":974,"lbm_read_time_us":11191,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21506,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:20:25.875568 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=10.126437
I20260812 06:20:25.914008 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.038s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16384,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.914626 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:25.926957 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.927528 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:25.954310 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1249,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1660,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:25.955039 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling LogGCOp(c0f316603e6b4aa5b6f7816019661a2d): free 124257239 bytes of WAL
I20260812 06:20:25.955336 24976 log_reader.cc:385] T c0f316603e6b4aa5b6f7816019661a2d: removed 12 log segments from log reader
I20260812 06:20:25.955394 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000003 (ops 12-16)
I20260812 06:20:25.955435 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000004 (ops 17-21)
I20260812 06:20:25.955493 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000005 (ops 22-26)
I20260812 06:20:25.955526 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000006 (ops 27-31)
I20260812 06:20:25.955557 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000007 (ops 32-36)
I20260812 06:20:25.955587 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000008 (ops 37-41)
I20260812 06:20:25.955618 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000009 (ops 42-46)
I20260812 06:20:25.955649 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000010 (ops 47-50)
I20260812 06:20:25.955679 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000011 (ops 51-55)
I20260812 06:20:25.955710 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000012 (ops 56-60)
I20260812 06:20:25.955749 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000013 (ops 61-65)
I20260812 06:20:25.955780 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000014 (ops 66-70)
I20260812 06:20:25.976970 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: LogGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:20:25.977505 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d): 462 bytes on disk
I20260812 06:20:25.977977 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d) 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:25.978609 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=3.181125
I20260812 06:20:25.998515 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4160,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.999042 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:26.008858 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3550,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.009327 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:26.210700 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.201s	user 0.142s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":959,"lbm_read_time_us":13577,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32008,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:20:26.211323 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:26.272186 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.061s	user 0.036s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21638,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.272850 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:26.283423 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.283952 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:26.470108 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.186s	user 0.119s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":896,"lbm_read_time_us":12202,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26411,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:26.470613 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:26.523806 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.053s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24234,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.524480 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:26.548537 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.024s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.549295 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:26.728958 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.179s	user 0.110s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":136,"lbm_read_time_us":11040,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26948,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25600,"update_count":2500}
I20260812 06:20:26.729493 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:26.777407 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":19058,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.778003 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:26.794831 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.795382 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:26.968755 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.173s	user 0.104s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":951,"lbm_read_time_us":9176,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28376,"lbm_writes_lt_1ms":543,"mutex_wait_us":289,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:26.969316 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:27.013656 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.044s	user 0.022s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17684,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.014268 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:27.025188 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.025740 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:27.170584 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.145s	user 0.114s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":90,"lbm_read_time_us":10806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25838,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:20:27.171368 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=11.118625
I20260812 06:20:27.206889 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14502,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:27.207518 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:27.220305 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.220842 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:27.347908 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.127s	user 0.111s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":7531,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25454,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:20:27.348555 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=10.126437
I20260812 06:20:27.394232 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.045s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13913,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.394817 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:27.405128 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.405751 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:27.434595 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.029s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1151,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1664,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:27.435326 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling LogGCOp(c0f316603e6b4aa5b6f7816019661a2d): free 121006436 bytes of WAL
I20260812 06:20:27.435599 24976 log_reader.cc:385] T c0f316603e6b4aa5b6f7816019661a2d: removed 12 log segments from log reader
I20260812 06:20:27.435663 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000015 (ops 71-75)
I20260812 06:20:27.435711 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000016 (ops 76-80)
I20260812 06:20:27.435741 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000017 (ops 81-85)
I20260812 06:20:27.435762 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000018 (ops 86-90)
I20260812 06:20:27.435793 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000019 (ops 91-94)
I20260812 06:20:27.435824 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000020 (ops 95-99)
I20260812 06:20:27.435851 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000021 (ops 100-104)
I20260812 06:20:27.435879 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000022 (ops 105-109)
I20260812 06:20:27.435907 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000023 (ops 110-114)
I20260812 06:20:27.435935 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000024 (ops 115-119)
I20260812 06:20:27.435966 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000025 (ops 120-124)
I20260812 06:20:27.435994 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000026 (ops 125-129)
I20260812 06:20:27.460492 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: LogGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:20:27.460979 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d): 471 bytes on disk
I20260812 06:20:27.461469 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: UndoDeltaBlockGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.462001 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=3.181125
I20260812 06:20:27.480644 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6744,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:27.481108 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:27.490768 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3447,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.491252 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:27.667784 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.176s	user 0.136s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":647,"lbm_read_time_us":12363,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31435,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:20:27.668418 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:27.716851 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.048s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20966,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.717510 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:27.734480 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.735049 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:27.899001 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.164s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":735,"lbm_read_time_us":10732,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26475,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:20:27.899808 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:27.953250 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.053s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.953893 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:28.103627 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.150s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":592,"lbm_read_time_us":8742,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24423,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35072,"update_count":2000}
I20260812 06:20:28.104290 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:28.151680 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.047s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.152338 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:28.164759 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.165555 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:28.348788 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.183s	user 0.112s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":676,"lbm_read_time_us":9415,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31221,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:20:28.349319 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:28.393712 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.044s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18902,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.394272 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:28.407681 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.408242 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:28.547406 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.139s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":9383,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25149,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:20:28.548236 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=11.118625
I20260812 06:20:28.579404 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.031s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":12741,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.580013 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:28.603183 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.023s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.603750 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:28.614269 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.614818 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:28.749902 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.135s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":449,"lbm_read_time_us":9546,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26362,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:20:28.750641 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=11.118625
I20260812 06:20:28.789745 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.039s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16791,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.790458 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=2.188937
I20260812 06:20:28.802879 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4870,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.803571 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:28.832481 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushMRSOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1198,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1563,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1280}
I20260812 06:20:28.833137 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling LogGCOp(c0f316603e6b4aa5b6f7816019661a2d): free 124710510 bytes of WAL
I20260812 06:20:28.833374 24976 log_reader.cc:385] T c0f316603e6b4aa5b6f7816019661a2d: removed 12 log segments from log reader
I20260812 06:20:28.833421 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000027 (ops 130-134)
I20260812 06:20:28.833449 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000028 (ops 135-138)
I20260812 06:20:28.833464 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000029 (ops 139-143)
I20260812 06:20:28.833487 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000030 (ops 144-148)
I20260812 06:20:28.833529 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000031 (ops 149-153)
I20260812 06:20:28.833554 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000032 (ops 154-158)
I20260812 06:20:28.833582 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000033 (ops 159-163)
I20260812 06:20:28.833616 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000034 (ops 164-169)
I20260812 06:20:28.833647 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000035 (ops 170-174)
I20260812 06:20:28.833676 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000036 (ops 175-179)
I20260812 06:20:28.833706 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000037 (ops 180-184)
I20260812 06:20:28.833734 24976 log.cc:1079] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: Deleting log segment in path: /tmp/dist-test-task3DN6kL/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515618985269-24420-0/minicluster-data/ts-0-root/wals/c0f316603e6b4aa5b6f7816019661a2d/wal-000000038 (ops 185-189)
I20260812 06:20:28.854940 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: LogGCOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:20:28.855484 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=4.173312
I20260812 06:20:28.871948 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":5661584,"delete_count":0,"lbm_write_time_us":6342,"lbm_writes_lt_1ms":141,"reinsert_count":0,"update_count":690}
I20260812 06:20:28.872537 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.196750
I20260812 06:20:28.884215 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":4078,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:20:28.884724 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=1.000000
I20260812 06:20:29.069010 24420 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.686s	user 1.712s	sys 0.133s
I20260812 06:20:29.072818 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: MajorDeltaCompactionOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.187s	user 0.138s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918289,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2499,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":666,"lbm_write_time_us":39401,"lbm_writes_lt_1ms":643,"mutex_wait_us":1248,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:20:29.073436 25098 maintenance_manager.cc:419] P d21b19661ba04527a8dd0876071d872d: Scheduling FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d): perf score=14.095187
I20260812 06:20:29.096511 24420 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.027s	user 0.002s	sys 0.000s
I20260812 06:20:29.097028 24420 tablet_server.cc:179] TabletServer@127.23.217.1:0 shutting down...
I20260812 06:20:29.120213 24976 maintenance_manager.cc:643] P d21b19661ba04527a8dd0876071d872d: FlushDeltaMemStoresOp(c0f316603e6b4aa5b6f7816019661a2d) complete. Timing: real 0.047s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20158,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.120849 24420 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:29.121058 24420 tablet_replica.cc:333] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d: stopping tablet replica
I20260812 06:20:29.121199 24420 raft_consensus.cc:2243] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:29.121376 24420 raft_consensus.cc:2272] T c0f316603e6b4aa5b6f7816019661a2d P d21b19661ba04527a8dd0876071d872d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.135118 24420 tablet_server.cc:196] TabletServer@127.23.217.1:0 shutdown complete.
I20260812 06:20:29.138062 24420 master.cc:562] Master@127.23.217.62:37223 shutting down...
I20260812 06:20:29.141037 24420 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:29.141204 24420 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:29.141256 24420 tablet_replica.cc:333] T 00000000000000000000000000000000 P 70626035ef424bdb8df0f734e3dc61ee: stopping tablet replica
I20260812 06:20:29.153604 24420 master.cc:584] Master@127.23.217.62:37223 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5054 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10227 ms total)

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