[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:57.094589 25600 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.0.62:37453
I20260812 06:18:57.095656 25600 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:57.096307 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.102833 25611 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.102806 25618 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:57.102890 25600 server_base.cc:1061] running on GCE node
W20260812 06:18:57.102808 25612 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:57.103461 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.103580 25600 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:57.103631 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515537103628 us; error 0 us; skew 500 ppm
I20260812 06:18:57.105762 25600 webserver.cc:533] Webserver started at http://127.25.0.62:38839/ using document root <none> and password file <none>
I20260812 06:18:57.106330 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.106390 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.106647 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.108209 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/master-0-root/instance:
uuid: "4eecff5a7573423db44463a0134b4207"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-68xk"
I20260812 06:18:57.111562 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:57.113763 25623 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.114796 25600 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:57.114923 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/master-0-root
uuid: "4eecff5a7573423db44463a0134b4207"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-68xk"
I20260812 06:18:57.115021 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:57.135118 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.135716 25600 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:57.135885 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.143271 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.62:37453
I20260812 06:18:57.143285 25707 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.62:37453 every 8 connection(s)
I20260812 06:18:57.145453 25708 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.150981 25708 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: Bootstrap starting.
I20260812 06:18:57.153256 25708 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.154134 25708 log.cc:826] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:57.155869 25708 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: No bootstrap required, opened a new log
I20260812 06:18:57.158597 25708 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4eecff5a7573423db44463a0134b4207" member_type: VOTER }
I20260812 06:18:57.158752 25708 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.158876 25708 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4eecff5a7573423db44463a0134b4207, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.159524 25708 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [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: "4eecff5a7573423db44463a0134b4207" member_type: VOTER }
I20260812 06:18:57.159700 25708 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.159773 25708 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.159919 25708 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.160687 25708 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4eecff5a7573423db44463a0134b4207" member_type: VOTER }
I20260812 06:18:57.161121 25708 leader_election.cc:304] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [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: 4eecff5a7573423db44463a0134b4207; no voters: 
I20260812 06:18:57.161432 25708 leader_election.cc:290] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.161515 25714 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.161830 25714 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 1 LEADER]: Becoming Leader. State: Replica: 4eecff5a7573423db44463a0134b4207, State: Running, Role: LEADER
I20260812 06:18:57.162227 25714 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [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: "4eecff5a7573423db44463a0134b4207" member_type: VOTER }
I20260812 06:18:57.162614 25708 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.164160 25716 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4eecff5a7573423db44463a0134b4207. Latest consensus state: current_term: 1 leader_uuid: "4eecff5a7573423db44463a0134b4207" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4eecff5a7573423db44463a0134b4207" member_type: VOTER } }
I20260812 06:18:57.164285 25717 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4eecff5a7573423db44463a0134b4207" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4eecff5a7573423db44463a0134b4207" member_type: VOTER } }
I20260812 06:18:57.164405 25717 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.164285 25716 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.164954 25600 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:57.167153 25733 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:57.167241 25733 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:57.167309 25729 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.168054 25729 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.172310 25729 catalog_manager.cc:1383] Generated new cluster ID: 2d6ffac4915242249fc60f8d94ece091
I20260812 06:18:57.172375 25729 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.183178 25729 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.184010 25729 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:57.190152 25729 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: Generated new TSK 0
I20260812 06:18:57.190840 25729 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:57.197728 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.200403 25740 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.200524 25741 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:57.200524 25748 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:57.200724 25600 server_base.cc:1061] running on GCE node
I20260812 06:18:57.200984 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.201048 25600 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:57.201074 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515537201073 us; error 0 us; skew 500 ppm
I20260812 06:18:57.202003 25600 webserver.cc:533] Webserver started at http://127.25.0.1:45321/ using document root <none> and password file <none>
I20260812 06:18:57.202189 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.202265 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.202345 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.202772 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/instance:
uuid: "0a1c4c6340f0405c872f33a4feb58ba5"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-68xk"
I20260812 06:18:57.204316 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:57.205358 25753 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.205632 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:57.205706 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root
uuid: "0a1c4c6340f0405c872f33a4feb58ba5"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-68xk"
I20260812 06:18:57.205798 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:57.211961 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.212361 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.212797 25600 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:57.213600 25600 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:57.213650 25600 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.213729 25600 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:57.213768 25600 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.220994 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.1:46811
I20260812 06:18:57.221031 25853 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.1:46811 every 8 connection(s)
I20260812 06:18:57.230823 25855 heartbeater.cc:344] Connected to a master server at 127.25.0.62:37453
I20260812 06:18:57.231066 25855 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:57.231490 25855 heartbeater.cc:507] Master 127.25.0.62:37453 requested a full tablet report, sending...
I20260812 06:18:57.232908 25653 ts_manager.cc:194] Registered new tserver with Master: 0a1c4c6340f0405c872f33a4feb58ba5 (127.25.0.1:46811)
I20260812 06:18:57.232990 25600 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011388041s
I20260812 06:18:57.234138 25653 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39606
I20260812 06:18:57.242605 25653 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39614:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:57.256387 25794 tablet_service.cc:1511] Processing CreateTablet for tablet 7013cfc93fcb4dfe8aeafd1fd04ada64 (DEFAULT_TABLE table=heavy-update-compaction-test [id=aaac18d3f1cd4e12959cb85a4e1502d2]), partition=
I20260812 06:18:57.256844 25794 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7013cfc93fcb4dfe8aeafd1fd04ada64. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.258921 25872 tablet_bootstrap.cc:492] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Bootstrap starting.
I20260812 06:18:57.260128 25872 tablet_bootstrap.cc:654] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.261207 25872 tablet_bootstrap.cc:492] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: No bootstrap required, opened a new log
I20260812 06:18:57.261328 25872 ts_tablet_manager.cc:1403] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:57.261750 25872 raft_consensus.cc:359] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a1c4c6340f0405c872f33a4feb58ba5" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 46811 } }
I20260812 06:18:57.261868 25872 raft_consensus.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.261934 25872 raft_consensus.cc:740] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0a1c4c6340f0405c872f33a4feb58ba5, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.262102 25872 consensus_queue.cc:260] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [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: "0a1c4c6340f0405c872f33a4feb58ba5" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 46811 } }
I20260812 06:18:57.262233 25872 raft_consensus.cc:399] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.262283 25872 raft_consensus.cc:493] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.262338 25872 raft_consensus.cc:3060] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.263070 25872 raft_consensus.cc:515] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a1c4c6340f0405c872f33a4feb58ba5" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 46811 } }
I20260812 06:18:57.263230 25872 leader_election.cc:304] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [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: 0a1c4c6340f0405c872f33a4feb58ba5; no voters: 
I20260812 06:18:57.263458 25872 leader_election.cc:290] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.263579 25885 raft_consensus.cc:2804] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.263850 25885 raft_consensus.cc:697] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 1 LEADER]: Becoming Leader. State: Replica: 0a1c4c6340f0405c872f33a4feb58ba5, State: Running, Role: LEADER
I20260812 06:18:57.263947 25872 ts_tablet_manager.cc:1434] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:57.264068 25885 consensus_queue.cc:237] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [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: "0a1c4c6340f0405c872f33a4feb58ba5" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 46811 } }
I20260812 06:18:57.264511 25855 heartbeater.cc:499] Master 127.25.0.62:37453 was elected leader, sending a full tablet report...
I20260812 06:18:57.266942 25653 catalog_manager.cc:5719] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0a1c4c6340f0405c872f33a4feb58ba5 (127.25.0.1). New cstate: current_term: 1 leader_uuid: "0a1c4c6340f0405c872f33a4feb58ba5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a1c4c6340f0405c872f33a4feb58ba5" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 46811 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:57.340251 25600 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.013s	sys 0.019s
I20260812 06:18:57.472004 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=19.054940
I20260812 06:18:57.625099 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.153s	user 0.126s	sys 0.024s Metrics: {"bytes_written":9025568,"cfile_init":1,"compiler_manager_pool.queue_time_us":203,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":796,"drs_written":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39122,"lbm_writes_lt_1ms":677,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":253184,"thread_start_us":138,"threads_started":1,"update_count":1100}
I20260812 06:18:57.626163 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): free 20743880 bytes of WAL
I20260812 06:18:57.626516 25762 log_reader.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64: removed 2 log segments from log reader
I20260812 06:18:57.626592 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000001 (ops 1-6)
I20260812 06:18:57.626672 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000002 (ops 7-11)
I20260812 06:18:57.632437 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:57.632930 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): 16411392 bytes on disk
I20260812 06:18:57.633651 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.634197 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:57.645603 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:18:57.646070 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:57.765585 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.119s	user 0.095s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569851,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":655,"lbm_read_time_us":7593,"lbm_reads_lt_1ms":360,"lbm_write_time_us":22303,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":269,"threads_started":5,"update_count":1500}
I20260812 06:18:57.766069 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:57.813269 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.047s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.813766 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:57.829735 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6170,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.830283 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:57.956048 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.126s	user 0.093s	sys 0.032s 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":924,"lbm_read_time_us":8581,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24441,"lbm_writes_lt_1ms":443,"mutex_wait_us":256,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:18:57.956593 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:58.006558 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.050s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15709,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.007161 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:58.017678 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.018054 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:58.167603 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.149s	user 0.095s	sys 0.054s 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":277,"lbm_read_time_us":11624,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25959,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:58.168195 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:58.217089 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.049s	user 0.008s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15409,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.217545 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:58.228981 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4351,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.229607 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:58.360841 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.131s	user 0.110s	sys 0.019s 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":254,"lbm_read_time_us":9353,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25351,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.361435 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:58.406836 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.045s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16979,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.407387 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:58.417891 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.418555 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:58.573442 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.155s	user 0.110s	sys 0.041s 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":337,"lbm_read_time_us":10350,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29154,"lbm_writes_lt_1ms":443,"mutex_wait_us":89,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:58.574132 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=11.118625
I20260812 06:18:58.622596 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.048s	user 0.017s	sys 0.031s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17817,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:58.623386 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:58.639072 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.639575 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:58.781654 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.142s	user 0.097s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":10627,"lbm_reads_lt_1ms":468,"lbm_write_time_us":22305,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:58.782315 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:58.827558 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.045s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16514,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.828086 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:58.838714 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.839155 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:58.982123 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.143s	user 0.110s	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":757,"lbm_read_time_us":9699,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30092,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:58.982808 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:18:59.031234 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.048s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17272,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.031868 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:59.083141 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.051s	user 0.023s	sys 0.008s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1300,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1853,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:59.083961 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): free 124257245 bytes of WAL
I20260812 06:18:59.084208 25762 log_reader.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64: removed 12 log segments from log reader
I20260812 06:18:59.084254 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000003 (ops 12-16)
I20260812 06:18:59.084285 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000004 (ops 17-20)
I20260812 06:18:59.084349 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000005 (ops 21-25)
I20260812 06:18:59.084393 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000006 (ops 26-30)
I20260812 06:18:59.084434 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000007 (ops 31-35)
I20260812 06:18:59.084475 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000008 (ops 36-40)
I20260812 06:18:59.084515 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000009 (ops 41-45)
I20260812 06:18:59.084554 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000010 (ops 46-50)
I20260812 06:18:59.084604 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000011 (ops 51-55)
I20260812 06:18:59.084643 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000012 (ops 56-60)
I20260812 06:18:59.084683 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000013 (ops 61-65)
I20260812 06:18:59.084723 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000014 (ops 66-70)
I20260812 06:18:59.113648 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:59.114162 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): 484 bytes on disk
I20260812 06:18:59.114784 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.115464 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=7.149875
I20260812 06:18:59.135596 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8607,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:59.136152 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:59.153365 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5538,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.153857 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:59.316604 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.163s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":522,"lbm_read_time_us":11843,"lbm_reads_lt_1ms":665,"lbm_write_time_us":32538,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:59.317296 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:18:59.370167 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.053s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22076,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.370680 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:59.394053 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.020s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5523,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:59.394541 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:59.403838 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3537,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.404235 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:59.575829 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.171s	user 0.133s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":254,"lbm_read_time_us":13945,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35659,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":3000}
I20260812 06:18:59.576454 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:18:59.627280 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.051s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24495,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.627996 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:59.641119 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.641717 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:18:59.820232 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.178s	user 0.114s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":11904,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34764,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:59.821024 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:18:59.885316 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.064s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25770,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.885784 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:18:59.896854 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.897338 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:00.073707 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.176s	user 0.134s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":903,"lbm_read_time_us":13830,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30787,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:19:00.074460 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=11.118625
I20260812 06:19:00.122459 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.048s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16049,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.123065 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:00.139025 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.139552 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:00.283738 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.144s	user 0.074s	sys 0.070s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":11597,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23243,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:19:00.284287 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:19:00.329596 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.045s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16952,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.330216 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:00.340639 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.341243 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:00.469978 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.129s	user 0.094s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":9150,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25368,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2000}
I20260812 06:19:00.470836 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:19:00.523216 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.052s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17585,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.523689 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:00.533763 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.534204 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:00.566514 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.032s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":152,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1291,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2249,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:00.567252 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): free 121459497 bytes of WAL
I20260812 06:19:00.567487 25762 log_reader.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64: removed 12 log segments from log reader
I20260812 06:19:00.567533 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000015 (ops 71-75)
I20260812 06:19:00.567561 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000016 (ops 76-80)
I20260812 06:19:00.567621 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000017 (ops 81-85)
I20260812 06:19:00.567662 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000018 (ops 86-90)
I20260812 06:19:00.567708 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000019 (ops 91-95)
I20260812 06:19:00.567744 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000020 (ops 96-100)
I20260812 06:19:00.567806 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000021 (ops 101-105)
I20260812 06:19:00.567840 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000022 (ops 106-110)
I20260812 06:19:00.567880 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000023 (ops 111-115)
I20260812 06:19:00.567920 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000024 (ops 116-120)
I20260812 06:19:00.567960 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000025 (ops 121-125)
I20260812 06:19:00.568004 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000026 (ops 126-130)
I20260812 06:19:00.595189 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.028s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:19:00.595624 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): 472 bytes on disk
I20260812 06:19:00.596086 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.596807 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=3.181125
I20260812 06:19:00.610494 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4307779,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:00.610961 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): free 11564893 bytes of WAL
I20260812 06:19:00.611196 25762 log_reader.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64: removed 1 log segments from log reader
I20260812 06:19:00.611263 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000027 (ops 131-134)
I20260812 06:19:00.614225 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:00.614580 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:00.629356 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3897533,"delete_count":0,"lbm_write_time_us":5572,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:00.630023 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:00.809438 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.179s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":218,"lbm_read_time_us":13755,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36513,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:00.810184 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:19:00.862542 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.052s	user 0.034s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18164,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.863104 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:00.878991 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.879714 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:01.050781 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.171s	user 0.145s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":11230,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33496,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:19:01.051469 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:19:01.106056 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.054s	user 0.022s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22944,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.106717 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:01.120239 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.120919 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:01.314354 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.193s	user 0.117s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":12674,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31036,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:19:01.318907 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:19:01.374946 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.055s	user 0.036s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24742,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.375515 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:01.392064 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.392518 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:01.551569 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.159s	user 0.100s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":11900,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26521,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:19:01.555480 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:19:01.602342 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.047s	user 0.017s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.602952 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:01.620265 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.620795 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:01.785866 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.165s	user 0.130s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":11875,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28516,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2500}
I20260812 06:19:01.786579 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=14.095187
I20260812 06:19:01.848919 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.062s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21966,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.849468 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:01.859934 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.860371 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:02.029496 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.169s	user 0.115s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":12660,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28033,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:02.030175 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=11.118625
I20260812 06:19:02.066699 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.036s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15609,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.067459 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:02.101979 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.034s	user 0.009s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5335,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.102648 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=2.188937
I20260812 06:19:02.113514 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.113934 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:02.147397 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushMRSOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.033s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1373,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1556,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:02.148111 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): 493 bytes on disk
I20260812 06:19:02.148572 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: UndoDeltaBlockGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.149118 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=1.000000
I20260812 06:19:02.265537 25600 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.925s	user 1.837s	sys 0.136s
I20260812 06:19:02.314754 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: MajorDeltaCompactionOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.165s	user 0.122s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":12700,"lbm_reads_lt_1ms":561,"lbm_write_time_us":29682,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:02.315321 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64): free 129320732 bytes of WAL
I20260812 06:19:02.315680 25762 log_reader.cc:385] T 7013cfc93fcb4dfe8aeafd1fd04ada64: removed 13 log segments from log reader
I20260812 06:19:02.315769 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000028 (ops 135-139)
I20260812 06:19:02.315825 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000029 (ops 140-144)
I20260812 06:19:02.315878 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000030 (ops 145-148)
I20260812 06:19:02.315918 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000031 (ops 149-153)
I20260812 06:19:02.315968 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000032 (ops 154-158)
I20260812 06:19:02.316005 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000033 (ops 159-163)
I20260812 06:19:02.316042 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000034 (ops 164-168)
I20260812 06:19:02.316079 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000035 (ops 169-173)
I20260812 06:19:02.316115 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000036 (ops 174-178)
I20260812 06:19:02.316152 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000037 (ops 179-182)
I20260812 06:19:02.316190 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000038 (ops 183-187)
I20260812 06:19:02.316227 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000039 (ops 188-192)
I20260812 06:19:02.316264 25762 log.cc:1079] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/7013cfc93fcb4dfe8aeafd1fd04ada64/wal-000000040 (ops 193-197)
I20260812 06:19:02.343716 25600 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.004s	sys 0.000s
I20260812 06:19:02.344247 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: LogGCOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:02.344497 25600 tablet_server.cc:179] TabletServer@127.25.0.1:0 shutting down...
I20260812 06:19:02.344776 25857 maintenance_manager.cc:419] P 0a1c4c6340f0405c872f33a4feb58ba5: Scheduling FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64): perf score=10.126437
I20260812 06:19:02.374805 25762 maintenance_manager.cc:643] P 0a1c4c6340f0405c872f33a4feb58ba5: FlushDeltaMemStoresOp(7013cfc93fcb4dfe8aeafd1fd04ada64) complete. Timing: real 0.030s	user 0.010s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13570,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.375510 25600 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.375893 25600 tablet_replica.cc:333] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5: stopping tablet replica
I20260812 06:19:02.376140 25600 raft_consensus.cc:2243] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.376408 25600 raft_consensus.cc:2272] T 7013cfc93fcb4dfe8aeafd1fd04ada64 P 0a1c4c6340f0405c872f33a4feb58ba5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.391119 25600 tablet_server.cc:196] TabletServer@127.25.0.1:0 shutdown complete.
I20260812 06:19:02.395895 25600 master.cc:562] Master@127.25.0.62:37453 shutting down...
I20260812 06:19:02.400477 25600 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.400624 25600 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.400678 25600 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4eecff5a7573423db44463a0134b4207: stopping tablet replica
I20260812 06:19:02.412925 25600 master.cc:584] Master@127.25.0.62:37453 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5408 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:02.514213 25600 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.0.62:36969
I20260812 06:19:02.514657 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.516796 25905 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.516821 25600 server_base.cc:1061] running on GCE node
W20260812 06:19:02.516908 25910 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.516979 25906 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:19:02.517237 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.517282 25600 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.517298 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515542517299 us; error 0 us; skew 500 ppm
I20260812 06:19:02.518096 25600 webserver.cc:533] Webserver started at http://127.25.0.62:38563/ using document root <none> and password file <none>
I20260812 06:19:02.518292 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.518335 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.519218 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.519649 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/master-0-root/instance:
uuid: "f0bc9776826249ad95fd3de35d45116e"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-68xk"
I20260812 06:19:02.521128 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:02.522063 25916 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.522295 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:02.522390 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/master-0-root
uuid: "f0bc9776826249ad95fd3de35d45116e"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-68xk"
I20260812 06:19:02.522505 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.530822 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.531167 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.535386 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.62:36969
I20260812 06:19:02.540686 26005 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.62:36969 every 8 connection(s)
I20260812 06:19:02.541127 26006 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.542909 26006 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e: Bootstrap starting.
I20260812 06:19:02.543663 26006 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.544644 26006 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e: No bootstrap required, opened a new log
I20260812 06:19:02.545043 26006 raft_consensus.cc:359] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER }
I20260812 06:19:02.545163 26006 raft_consensus.cc:385] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.545236 26006 raft_consensus.cc:740] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f0bc9776826249ad95fd3de35d45116e, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.545403 26006 consensus_queue.cc:260] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [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: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER }
I20260812 06:19:02.545495 26006 raft_consensus.cc:399] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.545545 26006 raft_consensus.cc:493] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.545604 26006 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.546257 26006 raft_consensus.cc:515] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER }
I20260812 06:19:02.546406 26006 leader_election.cc:304] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [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: f0bc9776826249ad95fd3de35d45116e; no voters: 
I20260812 06:19:02.546627 26006 leader_election.cc:290] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.546751 26009 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.546975 26009 raft_consensus.cc:697] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 1 LEADER]: Becoming Leader. State: Replica: f0bc9776826249ad95fd3de35d45116e, State: Running, Role: LEADER
I20260812 06:19:02.547086 26006 sys_catalog.cc:565] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.547114 26009 consensus_queue.cc:237] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [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: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER }
I20260812 06:19:02.547520 26010 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f0bc9776826249ad95fd3de35d45116e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER } }
I20260812 06:19:02.547614 26010 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.547577 26011 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [sys.catalog]: SysCatalogTable state changed. Reason: New leader f0bc9776826249ad95fd3de35d45116e. Latest consensus state: current_term: 1 leader_uuid: "f0bc9776826249ad95fd3de35d45116e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0bc9776826249ad95fd3de35d45116e" member_type: VOTER } }
I20260812 06:19:02.547719 26011 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.547891 26014 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.548853 26014 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.549095 25600 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.550755 26014 catalog_manager.cc:1383] Generated new cluster ID: 62409a6c2a7b428e8ef33fe452fad66f
I20260812 06:19:02.550810 26014 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.567014 26014 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.567533 26014 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.577876 26014 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e: Generated new TSK 0
I20260812 06:19:02.578070 26014 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.581395 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.583452 26035 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.583540 26042 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.583510 25600 server_base.cc:1061] running on GCE node
W20260812 06:19:02.583696 26040 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:19:02.583931 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.583973 25600 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.583988 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515542583989 us; error 0 us; skew 500 ppm
I20260812 06:19:02.584815 25600 webserver.cc:533] Webserver started at http://127.25.0.1:37587/ using document root <none> and password file <none>
I20260812 06:19:02.584950 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.584990 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.585080 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.585443 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/instance:
uuid: "8a778e954f6d4a7386e012a07597ffea"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-68xk"
I20260812 06:19:02.587025 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:02.587989 26056 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.588284 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:02.588354 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root
uuid: "8a778e954f6d4a7386e012a07597ffea"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-68xk"
I20260812 06:19:02.588454 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.609200 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.609618 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.609970 25600 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.610527 25600 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.610585 25600 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.610648 25600 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.610695 25600 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.615305 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.1:35507
I20260812 06:19:02.615861 26154 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.1:35507 every 8 connection(s)
I20260812 06:19:02.624294 26155 heartbeater.cc:344] Connected to a master server at 127.25.0.62:36969
I20260812 06:19:02.624403 26155 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.624639 26155 heartbeater.cc:507] Master 127.25.0.62:36969 requested a full tablet report, sending...
I20260812 06:19:02.625336 25948 ts_manager.cc:194] Registered new tserver with Master: 8a778e954f6d4a7386e012a07597ffea (127.25.0.1:35507)
I20260812 06:19:02.626065 25600 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010044716s
I20260812 06:19:02.626113 25948 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50130
I20260812 06:19:02.632956 25948 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50144:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:02.641602 26099 tablet_service.cc:1511] Processing CreateTablet for tablet ec25389ed6fc4307a6c1017289cc4604 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7bcddd9858f6461094595b87471fe16b]), partition=
I20260812 06:19:02.641884 26099 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ec25389ed6fc4307a6c1017289cc4604. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.643859 26183 tablet_bootstrap.cc:492] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Bootstrap starting.
I20260812 06:19:02.644704 26183 tablet_bootstrap.cc:654] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.645701 26183 tablet_bootstrap.cc:492] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: No bootstrap required, opened a new log
I20260812 06:19:02.645771 26183 ts_tablet_manager.cc:1403] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:02.646104 26183 raft_consensus.cc:359] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a778e954f6d4a7386e012a07597ffea" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35507 } }
I20260812 06:19:02.646186 26183 raft_consensus.cc:385] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.646209 26183 raft_consensus.cc:740] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8a778e954f6d4a7386e012a07597ffea, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.646338 26183 consensus_queue.cc:260] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [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: "8a778e954f6d4a7386e012a07597ffea" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35507 } }
I20260812 06:19:02.646477 26183 raft_consensus.cc:399] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.646548 26183 raft_consensus.cc:493] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.646610 26183 raft_consensus.cc:3060] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.647435 26183 raft_consensus.cc:515] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a778e954f6d4a7386e012a07597ffea" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35507 } }
I20260812 06:19:02.647550 26183 leader_election.cc:304] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [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: 8a778e954f6d4a7386e012a07597ffea; no voters: 
I20260812 06:19:02.647703 26183 leader_election.cc:290] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.647840 26189 raft_consensus.cc:2804] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.648063 26155 heartbeater.cc:499] Master 127.25.0.62:36969 was elected leader, sending a full tablet report...
I20260812 06:19:02.648080 26189 raft_consensus.cc:697] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 1 LEADER]: Becoming Leader. State: Replica: 8a778e954f6d4a7386e012a07597ffea, State: Running, Role: LEADER
I20260812 06:19:02.648068 26183 ts_tablet_manager.cc:1434] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:02.648240 26189 consensus_queue.cc:237] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [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: "8a778e954f6d4a7386e012a07597ffea" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35507 } }
I20260812 06:19:02.649503 25948 catalog_manager.cc:5719] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea reported cstate change: term changed from 0 to 1, leader changed from <none> to 8a778e954f6d4a7386e012a07597ffea (127.25.0.1). New cstate: current_term: 1 leader_uuid: "8a778e954f6d4a7386e012a07597ffea" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a778e954f6d4a7386e012a07597ffea" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35507 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.710472 25600 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.013s	sys 0.009s
I20260812 06:19:02.866581 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604): perf score=19.054940
I20260812 06:19:03.022341 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.156s	user 0.104s	sys 0.048s Metrics: {"bytes_written":11979303,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":801,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36047,"lbm_writes_lt_1ms":759,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":3840,"update_count":1460}
I20260812 06:19:03.023087 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling LogGCOp(ec25389ed6fc4307a6c1017289cc4604): free 20743880 bytes of WAL
I20260812 06:19:03.023294 26062 log_reader.cc:385] T ec25389ed6fc4307a6c1017289cc4604: removed 2 log segments from log reader
I20260812 06:19:03.023356 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000001 (ops 1-6)
I20260812 06:19:03.023399 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000002 (ops 7-11)
I20260812 06:19:03.028456 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: LogGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:03.028797 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=3.181125
I20260812 06:19:03.048972 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.020s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4430854,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:03.049412 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:03.058758 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.059338 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604): 16821648 bytes on disk
I20260812 06:19:03.059811 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.060330 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:03.236570 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.176s	user 0.113s	sys 0.063s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405557,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":591,"lbm_read_time_us":13023,"lbm_reads_lt_1ms":559,"lbm_write_time_us":29271,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"thread_start_us":304,"threads_started":5,"update_count":2450}
I20260812 06:19:03.237107 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:03.296167 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.059s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24996,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.296651 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:03.449744 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.153s	user 0.091s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":208,"lbm_read_time_us":10112,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23797,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:19:03.450476 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:03.504570 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.054s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.505100 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:03.515700 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.516245 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:03.695549 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.179s	user 0.121s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":652,"lbm_read_time_us":10163,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29434,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:19:03.696276 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:03.749225 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.053s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.749752 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:03.765512 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.766068 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:03.924201 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.158s	user 0.138s	sys 0.019s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":10289,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29881,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:19:03.924973 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=10.126437
I20260812 06:19:03.965898 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.041s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17703,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.966604 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:03.986505 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.020s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.987082 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:04.122460 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.135s	user 0.107s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":10349,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25743,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:19:04.123220 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=11.118625
I20260812 06:19:04.158595 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.035s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15823,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.159067 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:04.172578 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5022,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.173009 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:04.302983 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.130s	user 0.125s	sys 0.004s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713262,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":7929,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27523,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:19:04.303699 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=10.126437
I20260812 06:19:04.355252 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.051s	user 0.019s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18627,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.355850 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:04.366732 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.367201 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:04.410821 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.043s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1522,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1593,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:04.411466 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling LogGCOp(ec25389ed6fc4307a6c1017289cc4604): free 124710302 bytes of WAL
I20260812 06:19:04.411705 26062 log_reader.cc:385] T ec25389ed6fc4307a6c1017289cc4604: removed 12 log segments from log reader
I20260812 06:19:04.411753 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000003 (ops 12-16)
I20260812 06:19:04.411805 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000004 (ops 17-21)
I20260812 06:19:04.411851 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000005 (ops 22-26)
I20260812 06:19:04.411897 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000006 (ops 27-31)
I20260812 06:19:04.411939 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000007 (ops 32-36)
I20260812 06:19:04.412007 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000008 (ops 37-41)
I20260812 06:19:04.412046 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000009 (ops 42-46)
I20260812 06:19:04.412084 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000010 (ops 47-51)
I20260812 06:19:04.412124 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000011 (ops 52-56)
I20260812 06:19:04.412173 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000012 (ops 57-61)
I20260812 06:19:04.412213 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000013 (ops 62-66)
I20260812 06:19:04.412256 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000014 (ops 67-71)
I20260812 06:19:04.440227 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: LogGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:04.440615 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604): 471 bytes on disk
I20260812 06:19:04.441181 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.441653 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:04.463477 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.022s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.463933 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:04.474012 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.474462 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:04.688558 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.214s	user 0.182s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":421,"lbm_read_time_us":14835,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31730,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"thread_start_us":131,"threads_started":1,"update_count":3000}
I20260812 06:19:04.689568 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=16.079562
I20260812 06:19:04.737317 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.047s	user 0.025s	sys 0.020s Metrics: {"bytes_written":18214962,"delete_count":0,"lbm_write_time_us":21390,"lbm_writes_lt_1ms":447,"reinsert_count":0,"update_count":2220}
I20260812 06:19:04.737968 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.196750
I20260812 06:19:04.757831 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.020s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2707809,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:19:04.758275 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:04.767515 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.767913 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:04.969003 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.201s	user 0.129s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918171,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":564,"lbm_read_time_us":15778,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33611,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3000}
I20260812 06:19:04.969699 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=15.087375
I20260812 06:19:05.025928 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.056s	user 0.017s	sys 0.032s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":23764,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:05.026604 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.052430 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5459,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.052950 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.067391 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.067847 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:05.275722 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.208s	user 0.148s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1307,"lbm_read_time_us":14610,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33924,"lbm_writes_lt_1ms":643,"mutex_wait_us":418,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:19:05.276450 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:05.337073 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.060s	user 0.022s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23933,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.337682 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.349277 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.349797 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:05.524886 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.175s	user 0.132s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":13503,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29271,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:19:05.525635 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:05.578205 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.052s	user 0.030s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20723,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.578756 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.591248 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.012s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.592247 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:05.772290 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.180s	user 0.101s	sys 0.072s 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":372,"lbm_read_time_us":12336,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31980,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:05.772970 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:05.844187 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.071s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23497,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.844682 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.855410 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.855940 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:05.897173 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.041s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1365,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:05.897903 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling LogGCOp(ec25389ed6fc4307a6c1017289cc4604): free 120553339 bytes of WAL
I20260812 06:19:05.898159 26062 log_reader.cc:385] T ec25389ed6fc4307a6c1017289cc4604: removed 12 log segments from log reader
I20260812 06:19:05.898206 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000015 (ops 72-76)
I20260812 06:19:05.898244 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000016 (ops 77-81)
I20260812 06:19:05.898267 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000017 (ops 82-86)
I20260812 06:19:05.898295 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000018 (ops 87-91)
I20260812 06:19:05.898321 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000019 (ops 92-96)
I20260812 06:19:05.898350 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000020 (ops 97-100)
I20260812 06:19:05.898375 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000021 (ops 101-105)
I20260812 06:19:05.898399 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000022 (ops 106-110)
I20260812 06:19:05.898447 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000023 (ops 111-114)
I20260812 06:19:05.898473 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000024 (ops 115-119)
I20260812 06:19:05.898500 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000025 (ops 120-124)
I20260812 06:19:05.898526 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000026 (ops 125-129)
I20260812 06:19:05.927304 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: LogGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:05.927910 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=3.181125
I20260812 06:19:05.940975 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.013s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4348805,"delete_count":0,"lbm_write_time_us":4344,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:19:05.941442 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:05.953792 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:05.954351 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:06.194048 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.239s	user 0.170s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":280,"lbm_read_time_us":17550,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42599,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:06.195106 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=18.063937
I20260812 06:19:06.247689 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.052s	user 0.028s	sys 0.023s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23896,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.248281 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604): 462 bytes on disk
I20260812 06:19:06.248864 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.249644 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:06.270290 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.270830 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:06.441314 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.170s	user 0.125s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1104,"lbm_read_time_us":12092,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38620,"lbm_writes_lt_1ms":643,"mutex_wait_us":356,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":3000}
I20260812 06:19:06.442021 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:06.495360 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.053s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24750,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.495939 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:06.514667 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.515167 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:06.679760 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.164s	user 0.123s	sys 0.037s 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":247,"lbm_read_time_us":9526,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32717,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:06.680522 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:06.732853 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.052s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.733381 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:06.899293 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.166s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":759,"lbm_read_time_us":9987,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27287,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:19:06.899904 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:06.955451 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.055s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18668,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.955940 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:06.968114 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.968711 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:07.154093 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.185s	user 0.124s	sys 0.052s 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":207,"lbm_read_time_us":13224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29174,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:19:07.154835 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=14.095187
I20260812 06:19:07.207463 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.052s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19946,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.208003 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:07.219825 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.220480 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:07.385341 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.165s	user 0.134s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1484,"lbm_read_time_us":12046,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30661,"lbm_writes_lt_1ms":543,"mutex_wait_us":424,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2500}
I20260812 06:19:07.386346 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=11.118625
I20260812 06:19:07.417047 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.030s	user 0.014s	sys 0.014s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":13347,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:07.417762 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=2.188937
I20260812 06:19:07.432502 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5153,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.432974 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:07.463946 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushMRSOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1531,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:07.464603 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling LogGCOp(ec25389ed6fc4307a6c1017289cc4604): free 133024705 bytes of WAL
I20260812 06:19:07.464835 26062 log_reader.cc:385] T ec25389ed6fc4307a6c1017289cc4604: removed 13 log segments from log reader
I20260812 06:19:07.464897 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000027 (ops 130-134)
I20260812 06:19:07.464952 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000028 (ops 135-139)
I20260812 06:19:07.465010 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000029 (ops 140-144)
I20260812 06:19:07.465063 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000030 (ops 145-149)
I20260812 06:19:07.465101 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000031 (ops 150-154)
I20260812 06:19:07.465134 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000032 (ops 155-159)
I20260812 06:19:07.465173 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000033 (ops 160-164)
I20260812 06:19:07.465209 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000034 (ops 165-169)
I20260812 06:19:07.465245 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000035 (ops 170-174)
I20260812 06:19:07.465282 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000036 (ops 175-178)
I20260812 06:19:07.465319 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000037 (ops 179-183)
I20260812 06:19:07.465356 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000038 (ops 184-188)
I20260812 06:19:07.465394 26062 log.cc:1079] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: Deleting log segment in path: /tmp/dist-test-taskMNhOpU/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537083333-25600-0/minicluster-data/ts-0-root/wals/ec25389ed6fc4307a6c1017289cc4604/wal-000000039 (ops 189-193)
I20260812 06:19:07.497594 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: LogGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.033s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:19:07.498003 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=5.165500
I20260812 06:19:07.513926 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":6482065,"delete_count":0,"lbm_write_time_us":6721,"lbm_writes_lt_1ms":161,"reinsert_count":0,"update_count":790}
I20260812 06:19:07.514375 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604): 483 bytes on disk
I20260812 06:19:07.514830 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: UndoDeltaBlockGCOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.515640 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:07.524281 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1723202,"delete_count":0,"lbm_write_time_us":2773,"lbm_writes_lt_1ms":45,"reinsert_count":0,"update_count":210}
I20260812 06:19:07.524869 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604): perf score=1.000000
I20260812 06:19:07.681442 25600 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.971s	user 1.814s	sys 0.157s
I20260812 06:19:07.731704 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: MajorDeltaCompactionOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.207s	user 0.138s	sys 0.065s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":13385,"lbm_reads_lt_1ms":670,"lbm_write_time_us":36040,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":3000}
I20260812 06:19:07.732256 26157 maintenance_manager.cc:419] P 8a778e954f6d4a7386e012a07597ffea: Scheduling FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604): perf score=10.126437
I20260812 06:19:07.756560 25600 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.001s	sys 0.000s
I20260812 06:19:07.757103 25600 tablet_server.cc:179] TabletServer@127.25.0.1:0 shutting down...
I20260812 06:19:07.768179 26062 maintenance_manager.cc:643] P 8a778e954f6d4a7386e012a07597ffea: FlushDeltaMemStoresOp(ec25389ed6fc4307a6c1017289cc4604) complete. Timing: real 0.036s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15612,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.768731 25600 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.768993 25600 tablet_replica.cc:333] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea: stopping tablet replica
I20260812 06:19:07.769143 25600 raft_consensus.cc:2243] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.769368 25600 raft_consensus.cc:2272] T ec25389ed6fc4307a6c1017289cc4604 P 8a778e954f6d4a7386e012a07597ffea [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.784669 25600 tablet_server.cc:196] TabletServer@127.25.0.1:0 shutdown complete.
I20260812 06:19:07.788723 25600 master.cc:562] Master@127.25.0.62:36969 shutting down...
I20260812 06:19:07.792075 25600 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.792218 25600 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.792270 25600 tablet_replica.cc:333] T 00000000000000000000000000000000 P f0bc9776826249ad95fd3de35d45116e: stopping tablet replica
I20260812 06:19:07.804353 25600 master.cc:584] Master@127.25.0.62:36969 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5391 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10800 ms total)

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