[==========] 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:16.534662 14152 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.210.62:34201
I20260812 06:18:16.535645 14152 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:16.536258 14152 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:16.542560 14161 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:16.542645 14165 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:16.542783 14152 server_base.cc:1061] running on GCE node
W20260812 06:18:16.542941 14169 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:16.543430 14152 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:16.543532 14152 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:16.543574 14152 hybrid_clock.cc:648] HybridClock initialized: now 1786515496543571 us; error 0 us; skew 500 ppm
I20260812 06:18:16.545665 14152 webserver.cc:533] Webserver started at http://127.13.210.62:46873/ using document root <none> and password file <none>
I20260812 06:18:16.546307 14152 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:16.546378 14152 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:16.546690 14152 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:16.548295 14152 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/master-0-root/instance:
uuid: "71660c5992a947b487ce96caef308c9a"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-7lbf"
I20260812 06:18:16.551637 14152 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:16.553615 14174 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:16.554563 14152 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:16.554665 14152 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/master-0-root
uuid: "71660c5992a947b487ce96caef308c9a"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-7lbf"
I20260812 06:18:16.554754 14152 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-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:16.566079 14152 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:16.566635 14152 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:16.566784 14152 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:16.573627 14152 rpc_server.cc:307] RPC server started. Bound to: 127.13.210.62:34201
I20260812 06:18:16.573643 14261 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.210.62:34201 every 8 connection(s)
I20260812 06:18:16.575697 14262 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:16.580760 14262 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: Bootstrap starting.
I20260812 06:18:16.582994 14262 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:16.583793 14262 log.cc:826] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:16.585305 14262 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: No bootstrap required, opened a new log
I20260812 06:18:16.587863 14262 raft_consensus.cc:359] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71660c5992a947b487ce96caef308c9a" member_type: VOTER }
I20260812 06:18:16.588021 14262 raft_consensus.cc:385] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:16.588068 14262 raft_consensus.cc:740] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 71660c5992a947b487ce96caef308c9a, State: Initialized, Role: FOLLOWER
I20260812 06:18:16.588549 14262 consensus_queue.cc:260] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [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: "71660c5992a947b487ce96caef308c9a" member_type: VOTER }
I20260812 06:18:16.588670 14262 raft_consensus.cc:399] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:16.588712 14262 raft_consensus.cc:493] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:16.588794 14262 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:16.589453 14262 raft_consensus.cc:515] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71660c5992a947b487ce96caef308c9a" member_type: VOTER }
I20260812 06:18:16.589854 14262 leader_election.cc:304] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [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: 71660c5992a947b487ce96caef308c9a; no voters: 
I20260812 06:18:16.590124 14262 leader_election.cc:290] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:16.590232 14270 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:16.590435 14270 raft_consensus.cc:697] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 1 LEADER]: Becoming Leader. State: Replica: 71660c5992a947b487ce96caef308c9a, State: Running, Role: LEADER
I20260812 06:18:16.590858 14270 consensus_queue.cc:237] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [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: "71660c5992a947b487ce96caef308c9a" member_type: VOTER }
I20260812 06:18:16.591049 14262 sys_catalog.cc:565] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:16.592654 14272 sys_catalog.cc:455] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 71660c5992a947b487ce96caef308c9a. Latest consensus state: current_term: 1 leader_uuid: "71660c5992a947b487ce96caef308c9a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71660c5992a947b487ce96caef308c9a" member_type: VOTER } }
I20260812 06:18:16.592832 14272 sys_catalog.cc:458] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:16.592644 14271 sys_catalog.cc:455] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "71660c5992a947b487ce96caef308c9a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71660c5992a947b487ce96caef308c9a" member_type: VOTER } }
I20260812 06:18:16.593137 14271 sys_catalog.cc:458] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:16.593174 14152 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:16.593146 14292 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:16.595458 14292 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:16.599948 14292 catalog_manager.cc:1383] Generated new cluster ID: 9f34444244fc47b38e0cf9b7bb9256ef
I20260812 06:18:16.600001 14292 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:16.616858 14292 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:16.617695 14292 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:16.625551 14292 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: Generated new TSK 0
I20260812 06:18:16.626111 14292 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:16.657869 14152 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:16.660683 14298 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:16.660691 14299 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:16.660707 14302 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:16.660986 14152 server_base.cc:1061] running on GCE node
I20260812 06:18:16.661154 14152 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:16.661190 14152 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:16.661206 14152 hybrid_clock.cc:648] HybridClock initialized: now 1786515496661205 us; error 0 us; skew 500 ppm
I20260812 06:18:16.662066 14152 webserver.cc:533] Webserver started at http://127.13.210.1:37969/ using document root <none> and password file <none>
I20260812 06:18:16.662216 14152 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:16.662259 14152 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:16.662333 14152 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:16.662703 14152 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/instance:
uuid: "b386e82266c046df923941cceaac2827"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-7lbf"
I20260812 06:18:16.664129 14152 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:16.665040 14319 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:16.665295 14152 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:16.665359 14152 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root
uuid: "b386e82266c046df923941cceaac2827"
format_stamp: "Formatted at 2026-08-12 06:18:16 on dist-test-slave-7lbf"
I20260812 06:18:16.665441 14152 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-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:16.678133 14152 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:16.678529 14152 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:16.678974 14152 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:16.679776 14152 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:16.679824 14152 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:16.679868 14152 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:16.679898 14152 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:16.686149 14152 rpc_server.cc:307] RPC server started. Bound to: 127.13.210.1:45043
I20260812 06:18:16.686299 14439 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.210.1:45043 every 8 connection(s)
I20260812 06:18:16.695782 14440 heartbeater.cc:344] Connected to a master server at 127.13.210.62:34201
I20260812 06:18:16.696036 14440 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:16.696511 14440 heartbeater.cc:507] Master 127.13.210.62:34201 requested a full tablet report, sending...
I20260812 06:18:16.698160 14200 ts_manager.cc:194] Registered new tserver with Master: b386e82266c046df923941cceaac2827 (127.13.210.1:45043)
I20260812 06:18:16.698257 14152 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011486016s
I20260812 06:18:16.699632 14200 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45386
I20260812 06:18:16.707805 14200 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45398:
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:16.721181 14376 tablet_service.cc:1511] Processing CreateTablet for tablet 58d8486025b143abaa2559d0d88e1288 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1fe2633dbd2440958a59a37928ae81af]), partition=
I20260812 06:18:16.721611 14376 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 58d8486025b143abaa2559d0d88e1288. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:16.723909 14466 tablet_bootstrap.cc:492] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Bootstrap starting.
I20260812 06:18:16.725073 14466 tablet_bootstrap.cc:654] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:16.726322 14466 tablet_bootstrap.cc:492] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: No bootstrap required, opened a new log
I20260812 06:18:16.726433 14466 ts_tablet_manager.cc:1403] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:16.726963 14466 raft_consensus.cc:359] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b386e82266c046df923941cceaac2827" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 45043 } }
I20260812 06:18:16.727090 14466 raft_consensus.cc:385] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:16.727139 14466 raft_consensus.cc:740] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b386e82266c046df923941cceaac2827, State: Initialized, Role: FOLLOWER
I20260812 06:18:16.727294 14466 consensus_queue.cc:260] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [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: "b386e82266c046df923941cceaac2827" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 45043 } }
I20260812 06:18:16.727406 14466 raft_consensus.cc:399] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:16.727452 14466 raft_consensus.cc:493] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:16.727504 14466 raft_consensus.cc:3060] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:16.728418 14466 raft_consensus.cc:515] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b386e82266c046df923941cceaac2827" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 45043 } }
I20260812 06:18:16.728560 14466 leader_election.cc:304] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [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: b386e82266c046df923941cceaac2827; no voters: 
I20260812 06:18:16.728768 14466 leader_election.cc:290] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:16.728876 14468 raft_consensus.cc:2804] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:16.729072 14468 raft_consensus.cc:697] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 1 LEADER]: Becoming Leader. State: Replica: b386e82266c046df923941cceaac2827, State: Running, Role: LEADER
I20260812 06:18:16.729099 14466 ts_tablet_manager.cc:1434] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:16.729204 14468 consensus_queue.cc:237] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [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: "b386e82266c046df923941cceaac2827" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 45043 } }
I20260812 06:18:16.729499 14440 heartbeater.cc:499] Master 127.13.210.62:34201 was elected leader, sending a full tablet report...
I20260812 06:18:16.732100 14200 catalog_manager.cc:5719] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 reported cstate change: term changed from 0 to 1, leader changed from <none> to b386e82266c046df923941cceaac2827 (127.13.210.1). New cstate: current_term: 1 leader_uuid: "b386e82266c046df923941cceaac2827" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b386e82266c046df923941cceaac2827" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 45043 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:16.794275 14152 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.016s	sys 0.008s
I20260812 06:18:16.937332 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushMRSOp(58d8486025b143abaa2559d0d88e1288): perf score=19.054940
I20260812 06:18:17.094818 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushMRSOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.157s	user 0.122s	sys 0.027s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":244,"delete_count":0,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":826,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39327,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":131,"threads_started":1,"update_count":1450}
I20260812 06:18:17.095788 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling LogGCOp(58d8486025b143abaa2559d0d88e1288): free 20743880 bytes of WAL
I20260812 06:18:17.096061 14332 log_reader.cc:385] T 58d8486025b143abaa2559d0d88e1288: removed 2 log segments from log reader
I20260812 06:18:17.096118 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000001 (ops 1-6)
I20260812 06:18:17.096179 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000002 (ops 7-11)
I20260812 06:18:17.099897 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: LogGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:17.100215 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.114176 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.114697 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:17.248302 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.133s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303031,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":7283,"lbm_reads_lt_1ms":454,"lbm_write_time_us":22915,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":264,"threads_started":5,"update_count":1950}
I20260812 06:18:17.248857 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:17.290467 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.041s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.291020 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.301752 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.302333 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288): 16821648 bytes on disk
I20260812 06:18:17.302994 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.303515 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:17.418521 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.115s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1137,"lbm_read_time_us":8300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21183,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:17.419029 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:17.460898 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.042s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15722,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.461438 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.471285 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.471829 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:17.583323 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.111s	user 0.075s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":151,"lbm_read_time_us":7600,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21304,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.583910 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:17.625903 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.042s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13541,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.626403 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.636328 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.636749 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:17.772907 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.136s	user 0.070s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"lbm_read_time_us":10002,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22100,"lbm_writes_lt_1ms":443,"mutex_wait_us":258,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:18:17.773445 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:17.815064 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.041s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14233,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.815546 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.825476 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.825999 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:17.944725 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.119s	user 0.074s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":8677,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22632,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:17.945652 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:17.986400 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.041s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13039,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.986907 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:17.997357 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.997953 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:18.115747 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.118s	user 0.078s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":7782,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23233,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:18.116225 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:18.155938 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.040s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13536,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.156417 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:18.166823 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.167233 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:18.301664 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.134s	user 0.090s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":926,"lbm_read_time_us":9499,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22739,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.302155 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:18.343436 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.041s	user 0.011s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.343991 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:18.359340 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.359851 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushMRSOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:18.390285 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushMRSOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":303,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1934,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:18.391062 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling LogGCOp(58d8486025b143abaa2559d0d88e1288): free 133024360 bytes of WAL
I20260812 06:18:18.391275 14332 log_reader.cc:385] T 58d8486025b143abaa2559d0d88e1288: removed 13 log segments from log reader
I20260812 06:18:18.391320 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000003 (ops 12-16)
I20260812 06:18:18.391350 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000004 (ops 17-21)
I20260812 06:18:18.391381 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000005 (ops 22-26)
I20260812 06:18:18.391412 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000006 (ops 27-31)
I20260812 06:18:18.391443 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000007 (ops 32-36)
I20260812 06:18:18.391476 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000008 (ops 37-41)
I20260812 06:18:18.391510 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000009 (ops 42-46)
I20260812 06:18:18.391541 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000010 (ops 47-51)
I20260812 06:18:18.391573 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000011 (ops 52-56)
I20260812 06:18:18.391604 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000012 (ops 57-61)
I20260812 06:18:18.391635 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000013 (ops 62-66)
I20260812 06:18:18.391669 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000014 (ops 67-70)
I20260812 06:18:18.391691 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000015 (ops 71-75)
I20260812 06:18:18.416594 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: LogGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:18.417022 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288): 482 bytes on disk
I20260812 06:18:18.417552 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.418071 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=3.181125
I20260812 06:18:18.437294 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.019s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:18.437994 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:18.451946 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5060,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.452428 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:18.649394 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.197s	user 0.110s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3230,"lbm_read_time_us":13599,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30675,"lbm_writes_lt_1ms":643,"mutex_wait_us":2359,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:18.649889 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=14.095187
I20260812 06:18:18.705112 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.055s	user 0.040s	sys 0.010s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.705744 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:18.720664 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.721177 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:18.892231 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.171s	user 0.101s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":12505,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27819,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:18.892717 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=11.118625
I20260812 06:18:18.930044 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.037s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15604,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.930852 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:18.944665 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.945103 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.070796 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.126s	user 0.108s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":760,"lbm_read_time_us":7032,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24045,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28544,"update_count":2000}
I20260812 06:18:19.071209 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:19.106087 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.035s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14612,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":1500}
I20260812 06:18:19.106776 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.131644 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.132149 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.142020 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.142623 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.282682 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.140s	user 0.112s	sys 0.027s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":564,"lbm_read_time_us":8919,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27103,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:19.283442 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:19.316823 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.033s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12922,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.317310 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.331965 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.332559 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.457629 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.125s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":9512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20940,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34944,"update_count":2000}
I20260812 06:18:19.458197 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:19.500555 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.042s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.501197 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.511557 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.512027 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.659638 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.147s	user 0.123s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":9675,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24814,"lbm_writes_lt_1ms":443,"mutex_wait_us":255,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:19.660298 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:19.691167 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.031s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12706,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.692205 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.707710 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.708405 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushMRSOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.739621 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushMRSOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1406,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:19.740417 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling LogGCOp(58d8486025b143abaa2559d0d88e1288): free 111786264 bytes of WAL
I20260812 06:18:19.740643 14332 log_reader.cc:385] T 58d8486025b143abaa2559d0d88e1288: removed 11 log segments from log reader
I20260812 06:18:19.740685 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000016 (ops 76-80)
I20260812 06:18:19.740713 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000017 (ops 81-85)
I20260812 06:18:19.740741 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000018 (ops 86-90)
I20260812 06:18:19.740772 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000019 (ops 91-95)
I20260812 06:18:19.740804 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000020 (ops 96-100)
I20260812 06:18:19.740837 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000021 (ops 101-104)
I20260812 06:18:19.740869 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000022 (ops 105-109)
I20260812 06:18:19.740902 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000023 (ops 110-114)
I20260812 06:18:19.740935 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000024 (ops 115-119)
I20260812 06:18:19.740976 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000025 (ops 120-124)
I20260812 06:18:19.741009 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000026 (ops 125-128)
I20260812 06:18:19.760624 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: LogGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:18:19.761238 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=3.181125
I20260812 06:18:19.786430 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.025s	user 0.007s	sys 0.016s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":6657,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:19.786885 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288): 446 bytes on disk
I20260812 06:18:19.787287 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288) 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:18:19.787791 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:19.797739 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":3718,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:19.798120 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:19.986178 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.188s	user 0.129s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918332,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":594,"lbm_read_time_us":13661,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32695,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:18:19.986687 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=14.095187
I20260812 06:18:20.041599 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.055s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18528,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.042148 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:20.052500 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.052940 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:20.223286 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.170s	user 0.120s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":13021,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27135,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:20.229663 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=12.110812
I20260812 06:18:20.270569 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":14071527,"delete_count":0,"lbm_write_time_us":16714,"lbm_writes_lt_1ms":346,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1715}
I20260812 06:18:20.270995 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=1.196750
I20260812 06:18:20.281581 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2748834,"delete_count":0,"lbm_write_time_us":2679,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:18:20.282051 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:20.298280 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.016s	user 0.004s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.298770 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:20.468202 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.169s	user 0.135s	sys 0.030s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815761,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":120,"lbm_read_time_us":12536,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28595,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:18:20.468847 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=11.118625
I20260812 06:18:20.496821 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.028s	user 0.012s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":11601,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:20.497339 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:20.511869 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5464,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.512367 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:20.639472 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.127s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":7053,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26564,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:20.640075 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:20.684507 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20573,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.685006 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:20.698396 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.698889 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:20.815940 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.117s	user 0.093s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":951,"lbm_read_time_us":8997,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20797,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:20.816541 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:20.858740 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.042s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19702,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.859326 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:20.870882 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.871411 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:20.992802 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.121s	user 0.085s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":8772,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22718,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:20.993471 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=10.126437
I20260812 06:18:21.043965 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.050s	user 0.010s	sys 0.033s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.044597 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:21.054989 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3868,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.055462 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushMRSOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:21.085470 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushMRSOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.030s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1308,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1329,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:21.086148 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288): 448 bytes on disk
I20260812 06:18:21.086531 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: UndoDeltaBlockGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.087136 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:21.229398 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.142s	user 0.100s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":8648,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21613,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:21.230262 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling LogGCOp(58d8486025b143abaa2559d0d88e1288): free 121006655 bytes of WAL
I20260812 06:18:21.230497 14332 log_reader.cc:385] T 58d8486025b143abaa2559d0d88e1288: removed 12 log segments from log reader
I20260812 06:18:21.230917 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000027 (ops 129-133)
I20260812 06:18:21.230970 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000028 (ops 134-138)
I20260812 06:18:21.231004 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000029 (ops 139-143)
I20260812 06:18:21.231076 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000030 (ops 144-148)
I20260812 06:18:21.231119 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000031 (ops 149-153)
I20260812 06:18:21.231151 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000032 (ops 154-158)
I20260812 06:18:21.231189 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000033 (ops 159-163)
I20260812 06:18:21.231254 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000034 (ops 164-168)
I20260812 06:18:21.231297 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000035 (ops 169-173)
I20260812 06:18:21.231328 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000036 (ops 174-178)
I20260812 06:18:21.231383 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000037 (ops 179-182)
I20260812 06:18:21.231426 14332 log.cc:1079] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/58d8486025b143abaa2559d0d88e1288/wal-000000038 (ops 183-187)
I20260812 06:18:21.252995 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: LogGCOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.023s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:21.253382 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=15.087375
I20260812 06:18:21.296103 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.042s	user 0.033s	sys 0.005s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":17439,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:21.296663 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:21.323158 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.026s	user 0.014s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.323627 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=2.188937
I20260812 06:18:21.333109 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3478,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.333559 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288): perf score=1.000000
I20260812 06:18:21.435967 14152 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.642s	user 1.682s	sys 0.166s
I20260812 06:18:21.515802 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: MajorDeltaCompactionOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.182s	user 0.102s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":817,"lbm_read_time_us":14242,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31172,"lbm_writes_lt_1ms":643,"mutex_wait_us":265,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:18:21.517848 14441 maintenance_manager.cc:419] P b386e82266c046df923941cceaac2827: Scheduling FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288): perf score=6.157687
I20260812 06:18:21.522634 14152 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.001s	sys 0.003s
I20260812 06:18:21.523217 14152 tablet_server.cc:179] TabletServer@127.13.210.1:0 shutting down...
I20260812 06:18:21.539520 14332 maintenance_manager.cc:643] P b386e82266c046df923941cceaac2827: FlushDeltaMemStoresOp(58d8486025b143abaa2559d0d88e1288) complete. Timing: real 0.021s	user 0.009s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9590,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:21.540094 14152 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:21.540490 14152 tablet_replica.cc:333] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827: stopping tablet replica
I20260812 06:18:21.540706 14152 raft_consensus.cc:2243] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:21.540943 14152 raft_consensus.cc:2272] T 58d8486025b143abaa2559d0d88e1288 P b386e82266c046df923941cceaac2827 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:21.555984 14152 tablet_server.cc:196] TabletServer@127.13.210.1:0 shutdown complete.
I20260812 06:18:21.568749 14152 master.cc:562] Master@127.13.210.62:34201 shutting down...
I20260812 06:18:21.571903 14152 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:21.572072 14152 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:21.572140 14152 tablet_replica.cc:333] T 00000000000000000000000000000000 P 71660c5992a947b487ce96caef308c9a: stopping tablet replica
I20260812 06:18:21.584441 14152 master.cc:584] Master@127.13.210.62:34201 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5126 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:21.671047 14152 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.210.62:43767
I20260812 06:18:21.671463 14152 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:21.673380 14495 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:21.673491 14500 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:18:21.673668 14496 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:21.673712 14152 server_base.cc:1061] running on GCE node
I20260812 06:18:21.673947 14152 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:21.673988 14152 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:21.674002 14152 hybrid_clock.cc:648] HybridClock initialized: now 1786515501674003 us; error 0 us; skew 500 ppm
I20260812 06:18:21.674713 14152 webserver.cc:533] Webserver started at http://127.13.210.62:37387/ using document root <none> and password file <none>
I20260812 06:18:21.674844 14152 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:21.674881 14152 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:21.674939 14152 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:21.675259 14152 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/master-0-root/instance:
uuid: "bdff57a0cfd242298ebc4c6710d17075"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-7lbf"
I20260812 06:18:21.676592 14152 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:21.677390 14507 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:21.677640 14152 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:21.677711 14152 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/master-0-root
uuid: "bdff57a0cfd242298ebc4c6710d17075"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-7lbf"
I20260812 06:18:21.677778 14152 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-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:21.694154 14152 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:21.694512 14152 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:21.698428 14152 rpc_server.cc:307] RPC server started. Bound to: 127.13.210.62:43767
I20260812 06:18:21.702294 14615 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:21.702318 14612 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.210.62:43767 every 8 connection(s)
I20260812 06:18:21.704162 14615 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075: Bootstrap starting.
I20260812 06:18:21.705278 14615 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:21.706365 14615 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075: No bootstrap required, opened a new log
I20260812 06:18:21.706754 14615 raft_consensus.cc:359] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER }
I20260812 06:18:21.706840 14615 raft_consensus.cc:385] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:21.706866 14615 raft_consensus.cc:740] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bdff57a0cfd242298ebc4c6710d17075, State: Initialized, Role: FOLLOWER
I20260812 06:18:21.707006 14615 consensus_queue.cc:260] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [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: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER }
I20260812 06:18:21.707067 14615 raft_consensus.cc:399] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:21.707093 14615 raft_consensus.cc:493] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:21.707125 14615 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:21.707762 14615 raft_consensus.cc:515] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER }
I20260812 06:18:21.707872 14615 leader_election.cc:304] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [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: bdff57a0cfd242298ebc4c6710d17075; no voters: 
I20260812 06:18:21.708038 14615 leader_election.cc:290] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:21.708135 14620 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:21.708317 14620 raft_consensus.cc:697] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 1 LEADER]: Becoming Leader. State: Replica: bdff57a0cfd242298ebc4c6710d17075, State: Running, Role: LEADER
I20260812 06:18:21.708462 14615 sys_catalog.cc:565] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:21.708464 14620 consensus_queue.cc:237] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [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: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER }
I20260812 06:18:21.708933 14626 sys_catalog.cc:455] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bdff57a0cfd242298ebc4c6710d17075" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER } }
I20260812 06:18:21.708956 14627 sys_catalog.cc:455] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bdff57a0cfd242298ebc4c6710d17075. Latest consensus state: current_term: 1 leader_uuid: "bdff57a0cfd242298ebc4c6710d17075" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bdff57a0cfd242298ebc4c6710d17075" member_type: VOTER } }
I20260812 06:18:21.709028 14626 sys_catalog.cc:458] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:21.709048 14627 sys_catalog.cc:458] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:21.709255 14633 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:21.710124 14633 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:21.710342 14152 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:21.711796 14633 catalog_manager.cc:1383] Generated new cluster ID: f7fa475378e0425a8701d7febe90d696
I20260812 06:18:21.711850 14633 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:21.725533 14633 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:21.726064 14633 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:21.729553 14633 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075: Generated new TSK 0
I20260812 06:18:21.729703 14633 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:21.742514 14152 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:21.744393 14659 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:21.744521 14660 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:21.744518 14663 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:21.744645 14152 server_base.cc:1061] running on GCE node
I20260812 06:18:21.744863 14152 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:21.744910 14152 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:21.744925 14152 hybrid_clock.cc:648] HybridClock initialized: now 1786515501744925 us; error 0 us; skew 500 ppm
I20260812 06:18:21.745784 14152 webserver.cc:533] Webserver started at http://127.13.210.1:33875/ using document root <none> and password file <none>
I20260812 06:18:21.745937 14152 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:21.745994 14152 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:21.746068 14152 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:21.746428 14152 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/instance:
uuid: "726c7b5c50d34df3a1c046cbfd53a245"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-7lbf"
I20260812 06:18:21.747815 14152 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:21.748669 14672 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:21.748879 14152 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:21.748944 14152 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root
uuid: "726c7b5c50d34df3a1c046cbfd53a245"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-7lbf"
I20260812 06:18:21.749017 14152 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-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:21.754212 14152 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:21.754501 14152 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:21.754741 14152 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:21.755138 14152 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:21.755173 14152 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.755214 14152 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:21.755241 14152 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.759091 14152 rpc_server.cc:307] RPC server started. Bound to: 127.13.210.1:35421
I20260812 06:18:21.759951 14776 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.210.1:35421 every 8 connection(s)
I20260812 06:18:21.767218 14777 heartbeater.cc:344] Connected to a master server at 127.13.210.62:43767
I20260812 06:18:21.767328 14777 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:21.767571 14777 heartbeater.cc:507] Master 127.13.210.62:43767 requested a full tablet report, sending...
I20260812 06:18:21.768141 14536 ts_manager.cc:194] Registered new tserver with Master: 726c7b5c50d34df3a1c046cbfd53a245 (127.13.210.1:35421)
I20260812 06:18:21.768448 14152 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008772634s
I20260812 06:18:21.769078 14536 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58148
I20260812 06:18:21.775259 14536 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58152:
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:21.783187 14719 tablet_service.cc:1511] Processing CreateTablet for tablet 10f263a0895f480aa3c87417119f7c87 (DEFAULT_TABLE table=heavy-update-compaction-test [id=09fea293953648b7aaa4dcc96dd00a7f]), partition=
I20260812 06:18:21.783430 14719 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 10f263a0895f480aa3c87417119f7c87. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:21.785193 14803 tablet_bootstrap.cc:492] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Bootstrap starting.
I20260812 06:18:21.786113 14803 tablet_bootstrap.cc:654] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:21.787030 14803 tablet_bootstrap.cc:492] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: No bootstrap required, opened a new log
I20260812 06:18:21.787099 14803 ts_tablet_manager.cc:1403] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:21.787434 14803 raft_consensus.cc:359] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "726c7b5c50d34df3a1c046cbfd53a245" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 35421 } }
I20260812 06:18:21.787511 14803 raft_consensus.cc:385] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:21.787536 14803 raft_consensus.cc:740] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 726c7b5c50d34df3a1c046cbfd53a245, State: Initialized, Role: FOLLOWER
I20260812 06:18:21.787637 14803 consensus_queue.cc:260] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [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: "726c7b5c50d34df3a1c046cbfd53a245" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 35421 } }
I20260812 06:18:21.787722 14803 raft_consensus.cc:399] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:21.787751 14803 raft_consensus.cc:493] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:21.787786 14803 raft_consensus.cc:3060] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:21.788427 14803 raft_consensus.cc:515] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "726c7b5c50d34df3a1c046cbfd53a245" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 35421 } }
I20260812 06:18:21.788539 14803 leader_election.cc:304] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [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: 726c7b5c50d34df3a1c046cbfd53a245; no voters: 
I20260812 06:18:21.788717 14803 leader_election.cc:290] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:21.788818 14805 raft_consensus.cc:2804] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:21.789026 14803 ts_tablet_manager.cc:1434] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:21.789028 14777 heartbeater.cc:499] Master 127.13.210.62:43767 was elected leader, sending a full tablet report...
I20260812 06:18:21.789115 14805 raft_consensus.cc:697] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 1 LEADER]: Becoming Leader. State: Replica: 726c7b5c50d34df3a1c046cbfd53a245, State: Running, Role: LEADER
I20260812 06:18:21.789232 14805 consensus_queue.cc:237] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [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: "726c7b5c50d34df3a1c046cbfd53a245" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 35421 } }
I20260812 06:18:21.790436 14536 catalog_manager.cc:5719] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 reported cstate change: term changed from 0 to 1, leader changed from <none> to 726c7b5c50d34df3a1c046cbfd53a245 (127.13.210.1). New cstate: current_term: 1 leader_uuid: "726c7b5c50d34df3a1c046cbfd53a245" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "726c7b5c50d34df3a1c046cbfd53a245" member_type: VOTER last_known_addr { host: "127.13.210.1" port: 35421 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:21.844877 14152 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.008s
I20260812 06:18:22.010411 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushMRSOp(10f263a0895f480aa3c87417119f7c87): perf score=23.023690
I20260812 06:18:22.161173 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushMRSOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.151s	user 0.099s	sys 0.048s Metrics: {"bytes_written":12307494,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":962,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40215,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:22.161921 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling LogGCOp(10f263a0895f480aa3c87417119f7c87): free 20743880 bytes of WAL
I20260812 06:18:22.162153 14680 log_reader.cc:385] T 10f263a0895f480aa3c87417119f7c87: removed 2 log segments from log reader
I20260812 06:18:22.162204 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000001 (ops 1-6)
I20260812 06:18:22.162235 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000002 (ops 7-11)
I20260812 06:18:22.165793 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: LogGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:22.166118 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87): 20513816 bytes on disk
I20260812 06:18:22.166525 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.166913 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:22.179630 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.180027 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:22.322103 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.142s	user 0.086s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":420,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24103,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":292,"threads_started":5,"update_count":2000}
I20260812 06:18:22.322631 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:22.363008 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.040s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12444,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:18:22.363592 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:22.378724 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.379208 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:22.531837 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.152s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":10999,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25113,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:22.532536 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:22.578531 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.046s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15980,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.579018 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:22.588877 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.589457 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:22.708657 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.119s	user 0.086s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":94,"lbm_read_time_us":8754,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22368,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:18:22.709571 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:22.752177 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.042s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15970,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.752730 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:22.767940 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.768549 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:22.896267 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":9535,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24788,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2000}
I20260812 06:18:22.896867 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:22.948886 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.052s	user 0.029s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18067,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.949282 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:22.959370 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.959784 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.123281 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.163s	user 0.101s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":179,"lbm_read_time_us":11219,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27714,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:18:23.123867 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:23.163497 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.039s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.164005 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:23.174322 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.174911 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.296339 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":97,"lbm_read_time_us":8122,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23403,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":42496,"update_count":2000}
I20260812 06:18:23.297029 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:23.334102 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.037s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16917,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.334671 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:23.347265 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.347759 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushMRSOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.373199 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushMRSOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.025s	user 0.020s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1322,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1746,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:23.373834 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling LogGCOp(10f263a0895f480aa3c87417119f7c87): free 112692363 bytes of WAL
I20260812 06:18:23.374053 14680 log_reader.cc:385] T 10f263a0895f480aa3c87417119f7c87: removed 11 log segments from log reader
I20260812 06:18:23.374101 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000003 (ops 12-16)
I20260812 06:18:23.374128 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000004 (ops 17-21)
I20260812 06:18:23.374159 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000005 (ops 22-26)
I20260812 06:18:23.374190 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000006 (ops 27-31)
I20260812 06:18:23.374222 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000007 (ops 32-36)
I20260812 06:18:23.374254 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000008 (ops 37-41)
I20260812 06:18:23.374285 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000009 (ops 42-46)
I20260812 06:18:23.374316 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000010 (ops 47-51)
I20260812 06:18:23.374347 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000011 (ops 52-56)
I20260812 06:18:23.374380 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000012 (ops 57-61)
I20260812 06:18:23.374411 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000013 (ops 62-66)
I20260812 06:18:23.395483 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: LogGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:23.395900 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=3.181125
I20260812 06:18:23.409826 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:23.410290 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:23.419500 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3247,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.419919 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.586133 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.166s	user 0.138s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":344,"lbm_read_time_us":13283,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31522,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6272,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:23.586561 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=14.095187
I20260812 06:18:23.634027 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.634538 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:23.644593 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.645215 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.801426 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.156s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":9475,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32088,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2500}
I20260812 06:18:23.802142 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87): 447 bytes on disk
I20260812 06:18:23.802728 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.803267 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=12.110812
I20260812 06:18:23.842481 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.039s	user 0.034s	sys 0.004s Metrics: {"bytes_written":14440742,"delete_count":0,"lbm_write_time_us":16547,"lbm_writes_lt_1ms":355,"reinsert_count":0,"update_count":1760}
I20260812 06:18:23.843041 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=1.196750
I20260812 06:18:23.850217 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.007s	user 0.005s	sys 0.001s Metrics: {"bytes_written":2379608,"delete_count":0,"lbm_write_time_us":2369,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:18:23.850621 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:23.993055 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.142s	user 0.084s	sys 0.046s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21123473,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":9130,"lbm_reads_lt_1ms":474,"lbm_write_time_us":20782,"lbm_writes_lt_1ms":453,"mutex_wait_us":331,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2050}
I20260812 06:18:23.993615 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=14.095187
I20260812 06:18:24.038708 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.045s	user 0.018s	sys 0.022s Metrics: {"bytes_written":15999664,"delete_count":0,"lbm_write_time_us":17407,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:18:24.039163 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.057904 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.019s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.058404 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:24.233415 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.175s	user 0.118s	sys 0.054s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405446,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":12230,"lbm_reads_lt_1ms":562,"lbm_write_time_us":27621,"lbm_writes_lt_1ms":533,"mutex_wait_us":63,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2450}
I20260812 06:18:24.234001 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=11.118625
I20260812 06:18:24.267373 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13807,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:24.268056 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.279950 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.280439 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:24.397576 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.117s	user 0.097s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":665,"lbm_read_time_us":6708,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23336,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:18:24.398156 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:24.433868 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.036s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13750,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.434405 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.444231 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.444670 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:24.575801 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.131s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":10099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23117,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.576560 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=10.126437
I20260812 06:18:24.617383 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.041s	user 0.014s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.617952 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.627848 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.628592 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushMRSOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:24.655536 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushMRSOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.027s	user 0.017s	sys 0.007s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1294,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1377,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:24.656226 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling LogGCOp(10f263a0895f480aa3c87417119f7c87): free 124257249 bytes of WAL
I20260812 06:18:24.656471 14680 log_reader.cc:385] T 10f263a0895f480aa3c87417119f7c87: removed 12 log segments from log reader
I20260812 06:18:24.656533 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000014 (ops 67-71)
I20260812 06:18:24.656574 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000015 (ops 72-76)
I20260812 06:18:24.656606 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000016 (ops 77-81)
I20260812 06:18:24.656636 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000017 (ops 82-86)
I20260812 06:18:24.656666 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000018 (ops 87-91)
I20260812 06:18:24.656692 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000019 (ops 92-96)
I20260812 06:18:24.656718 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000020 (ops 97-101)
I20260812 06:18:24.656747 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000021 (ops 102-106)
I20260812 06:18:24.656780 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000022 (ops 107-111)
I20260812 06:18:24.656809 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000023 (ops 112-116)
I20260812 06:18:24.656837 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000024 (ops 117-120)
I20260812 06:18:24.656858 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000025 (ops 121-125)
I20260812 06:18:24.684829 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: LogGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:24.685256 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=3.181125
I20260812 06:18:24.700116 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:24.700519 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.714654 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5125,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.715133 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:24.882247 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.167s	user 0.106s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":780,"lbm_read_time_us":13646,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31931,"lbm_writes_lt_1ms":643,"mutex_wait_us":307,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:24.882797 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=14.095187
I20260812 06:18:24.928949 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.046s	user 0.026s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17939,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.929548 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87): 447 bytes on disk
I20260812 06:18:24.929991 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.930549 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:24.941074 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.941655 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:25.093503 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.152s	user 0.125s	sys 0.020s 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":270,"lbm_read_time_us":9193,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29085,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:25.094103 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=11.118625
I20260812 06:18:25.123960 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.030s	user 0.023s	sys 0.004s Metrics: {"bytes_written":12717766,"delete_count":0,"lbm_write_time_us":13045,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:18:25.124441 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.136816 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.137312 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:25.285173 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.148s	user 0.095s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713294,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":925,"lbm_read_time_us":11162,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23025,"lbm_writes_lt_1ms":443,"mutex_wait_us":305,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:18:25.285827 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=11.118625
I20260812 06:18:25.326478 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.040s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13740,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.327061 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.356333 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.029s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4927,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.356884 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.366670 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.367094 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:25.533761 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.167s	user 0.103s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":178,"lbm_read_time_us":10749,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25615,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.534253 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=14.095187
I20260812 06:18:25.593765 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.059s	user 0.026s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.594326 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.604831 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.605301 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:25.793007 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.188s	user 0.113s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3183,"lbm_read_time_us":12304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29598,"lbm_writes_lt_1ms":543,"mutex_wait_us":2561,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:25.793625 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=11.118625
I20260812 06:18:25.830056 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.036s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12758764,"delete_count":0,"lbm_write_time_us":15605,"lbm_writes_lt_1ms":314,"reinsert_count":0,"update_count":1555}
I20260812 06:18:25.830550 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.861207 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.028s	user 0.003s	sys 0.014s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:25.861789 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:25.871186 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3395,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.871708 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:26.053618 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.182s	user 0.106s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":659,"lbm_read_time_us":11927,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26757,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:18:26.054199 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=14.095187
I20260812 06:18:26.100986 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.047s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17889,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.101586 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:26.111600 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.112529 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushMRSOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:26.150041 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushMRSOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.037s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1526,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1617,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:26.150740 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling LogGCOp(10f263a0895f480aa3c87417119f7c87): free 124257498 bytes of WAL
I20260812 06:18:26.150954 14680 log_reader.cc:385] T 10f263a0895f480aa3c87417119f7c87: removed 12 log segments from log reader
I20260812 06:18:26.151000 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000026 (ops 126-130)
I20260812 06:18:26.151028 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000027 (ops 131-134)
I20260812 06:18:26.151058 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000028 (ops 135-139)
I20260812 06:18:26.151090 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000029 (ops 140-144)
I20260812 06:18:26.151113 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000030 (ops 145-149)
I20260812 06:18:26.151129 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000031 (ops 150-154)
I20260812 06:18:26.151160 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000032 (ops 155-159)
I20260812 06:18:26.151191 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000033 (ops 160-164)
I20260812 06:18:26.151222 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000034 (ops 165-169)
I20260812 06:18:26.151253 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000035 (ops 170-174)
I20260812 06:18:26.151283 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000036 (ops 175-179)
I20260812 06:18:26.151315 14680 log.cc:1079] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: Deleting log segment in path: /tmp/dist-test-task9NQEiw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515496524002-14152-0/minicluster-data/ts-0-root/wals/10f263a0895f480aa3c87417119f7c87/wal-000000037 (ops 180-184)
I20260812 06:18:26.172094 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: LogGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:26.172509 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:26.194931 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.195417 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:26.205343 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.205807 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:26.420212 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.214s	user 0.139s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020747,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1937,"lbm_read_time_us":13885,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35756,"lbm_writes_lt_1ms":743,"mutex_wait_us":703,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:26.420928 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=16.079562
I20260812 06:18:26.475396 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.054s	user 0.034s	sys 0.016s Metrics: {"bytes_written":18255987,"delete_count":0,"lbm_write_time_us":23185,"lbm_writes_lt_1ms":448,"reinsert_count":0,"update_count":2225}
I20260812 06:18:26.475914 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87): 483 bytes on disk
I20260812 06:18:26.476305 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: UndoDeltaBlockGCOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.476817 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=1.196750
I20260812 06:18:26.485425 14152 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.640s	user 1.689s	sys 0.152s
I20260812 06:18:26.486585 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.010s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2666783,"delete_count":0,"lbm_write_time_us":2533,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:18:26.486939 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87): perf score=2.188937
I20260812 06:18:26.495218 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: FlushDeltaMemStoresOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3394,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":450}
I20260812 06:18:26.495568 14780 maintenance_manager.cc:419] P 726c7b5c50d34df3a1c046cbfd53a245: Scheduling MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87): perf score=1.000000
I20260812 06:18:26.558363 14152 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.002s	sys 0.000s
I20260812 06:18:26.558864 14152 tablet_server.cc:179] TabletServer@127.13.210.1:0 shutting down...
I20260812 06:18:26.644361 14680 maintenance_manager.cc:643] P 726c7b5c50d34df3a1c046cbfd53a245: MajorDeltaCompactionOp(10f263a0895f480aa3c87417119f7c87) complete. Timing: real 0.149s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_hit":166,"cfile_cache_hit_bytes":6732702,"cfile_cache_miss":467,"cfile_cache_miss_bytes":22185468,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1100,"lbm_read_time_us":8699,"lbm_reads_lt_1ms":499,"lbm_write_time_us":27066,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":44416,"update_count":3000}
I20260812 06:18:26.644948 14152 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:26.645255 14152 tablet_replica.cc:333] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245: stopping tablet replica
I20260812 06:18:26.645372 14152 raft_consensus.cc:2243] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:26.645588 14152 raft_consensus.cc:2272] T 10f263a0895f480aa3c87417119f7c87 P 726c7b5c50d34df3a1c046cbfd53a245 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:26.648785 14152 tablet_server.cc:196] TabletServer@127.13.210.1:0 shutdown complete.
I20260812 06:18:26.697021 14152 master.cc:562] Master@127.13.210.62:43767 shutting down...
I20260812 06:18:26.700264 14152 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:26.700443 14152 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:26.700517 14152 tablet_replica.cc:333] T 00000000000000000000000000000000 P bdff57a0cfd242298ebc4c6710d17075: stopping tablet replica
I20260812 06:18:26.712697 14152 master.cc:584] Master@127.13.210.62:43767 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5129 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10256 ms total)

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