[==========] 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:17:46.039227 27497 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.218.126:45901
I20260812 06:17:46.040202 27497 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:17:46.040787 27497 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:46.046916 27497 server_base.cc:1061] running on GCE node
W20260812 06:17:46.046979 27508 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:17:46.047109 27511 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:17:46.047290 27506 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:46.047732 27497 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.047869 27497 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:17:46.047909 27497 hybrid_clock.cc:648] HybridClock initialized: now 1786515466047907 us; error 0 us; skew 500 ppm
I20260812 06:17:46.049605 27497 webserver.cc:533] Webserver started at http://127.26.218.126:38173/ using document root <none> and password file <none>
I20260812 06:17:46.050132 27497 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.050220 27497 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.050462 27497 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.052052 27497 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/master-0-root/instance:
uuid: "8d06df284010483887c200ce516ef2ab"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-7nm7"
I20260812 06:17:46.055471 27497 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:46.057479 27522 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:17:46.058511 27497 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:46.058655 27497 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/master-0-root
uuid: "8d06df284010483887c200ce516ef2ab"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-7nm7"
I20260812 06:17:46.058763 27497 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-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:17:46.082019 27497 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.082762 27497 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:17:46.082968 27497 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.091969 27497 rpc_server.cc:307] RPC server started. Bound to: 127.26.218.126:45901
I20260812 06:17:46.092020 27606 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.218.126:45901 every 8 connection(s)
I20260812 06:17:46.094427 27607 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:17:46.099929 27607 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: Bootstrap starting.
I20260812 06:17:46.102661 27607 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.103607 27607 log.cc:826] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:46.105432 27607 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: No bootstrap required, opened a new log
I20260812 06:17:46.108316 27607 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d06df284010483887c200ce516ef2ab" member_type: VOTER }
I20260812 06:17:46.108492 27607 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.108538 27607 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8d06df284010483887c200ce516ef2ab, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.109184 27607 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [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: "8d06df284010483887c200ce516ef2ab" member_type: VOTER }
I20260812 06:17:46.109352 27607 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.109400 27607 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.109493 27607 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.110404 27607 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d06df284010483887c200ce516ef2ab" member_type: VOTER }
I20260812 06:17:46.110818 27607 leader_election.cc:304] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [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: 8d06df284010483887c200ce516ef2ab; no voters: 
I20260812 06:17:46.111119 27607 leader_election.cc:290] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.111336 27614 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.111583 27614 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 1 LEADER]: Becoming Leader. State: Replica: 8d06df284010483887c200ce516ef2ab, State: Running, Role: LEADER
I20260812 06:17:46.111958 27614 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [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: "8d06df284010483887c200ce516ef2ab" member_type: VOTER }
I20260812 06:17:46.112278 27607 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:46.114066 27618 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8d06df284010483887c200ce516ef2ab. Latest consensus state: current_term: 1 leader_uuid: "8d06df284010483887c200ce516ef2ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d06df284010483887c200ce516ef2ab" member_type: VOTER } }
I20260812 06:17:46.114214 27618 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.114179 27616 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8d06df284010483887c200ce516ef2ab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d06df284010483887c200ce516ef2ab" member_type: VOTER } }
I20260812 06:17:46.114297 27616 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.114676 27634 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:46.117305 27634 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:46.117754 27497 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:46.122197 27634 catalog_manager.cc:1383] Generated new cluster ID: a323483d8adf44149eece478f859db51
I20260812 06:17:46.122289 27634 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:46.131445 27634 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:46.132232 27634 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:46.138146 27634 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: Generated new TSK 0
I20260812 06:17:46.138732 27634 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:46.150164 27497 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.152722 27648 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:17:46.152776 27647 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:17:46.152813 27651 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:17:46.153323 27497 server_base.cc:1061] running on GCE node
I20260812 06:17:46.153509 27497 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.153563 27497 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:17:46.153589 27497 hybrid_clock.cc:648] HybridClock initialized: now 1786515466153587 us; error 0 us; skew 500 ppm
I20260812 06:17:46.154573 27497 webserver.cc:533] Webserver started at http://127.26.218.65:33339/ using document root <none> and password file <none>
I20260812 06:17:46.154748 27497 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.154812 27497 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.154893 27497 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.155344 27497 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/instance:
uuid: "098a60bd14ce46f19f3e0fec7c40e61f"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-7nm7"
I20260812 06:17:46.157325 27497 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:46.158557 27662 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:17:46.158831 27497 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:46.158905 27497 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root
uuid: "098a60bd14ce46f19f3e0fec7c40e61f"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-7nm7"
I20260812 06:17:46.158955 27497 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-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:17:46.167050 27497 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.167505 27497 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.167968 27497 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:46.168910 27497 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:46.168967 27497 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.169035 27497 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:46.169080 27497 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.176596 27497 rpc_server.cc:307] RPC server started. Bound to: 127.26.218.65:34359
I20260812 06:17:46.176631 27772 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.218.65:34359 every 8 connection(s)
I20260812 06:17:46.190177 27773 heartbeater.cc:344] Connected to a master server at 127.26.218.126:45901
I20260812 06:17:46.190496 27773 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:46.191025 27773 heartbeater.cc:507] Master 127.26.218.126:45901 requested a full tablet report, sending...
I20260812 06:17:46.192687 27544 ts_manager.cc:194] Registered new tserver with Master: 098a60bd14ce46f19f3e0fec7c40e61f (127.26.218.65:34359)
I20260812 06:17:46.192932 27497 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01567916s
I20260812 06:17:46.194404 27544 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:32878
I20260812 06:17:46.203224 27544 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:32888:
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:17:46.217492 27715 tablet_service.cc:1511] Processing CreateTablet for tablet e96484d7f9d0456fa0ff90e102b7bcb4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cf8c93319e6c4da98bfcd9bdbd3c9c27]), partition=
I20260812 06:17:46.217985 27715 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e96484d7f9d0456fa0ff90e102b7bcb4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:46.220258 27789 tablet_bootstrap.cc:492] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Bootstrap starting.
I20260812 06:17:46.221268 27789 tablet_bootstrap.cc:654] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.222539 27789 tablet_bootstrap.cc:492] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: No bootstrap required, opened a new log
I20260812 06:17:46.222642 27789 ts_tablet_manager.cc:1403] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:46.223078 27789 raft_consensus.cc:359] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "098a60bd14ce46f19f3e0fec7c40e61f" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 34359 } }
I20260812 06:17:46.223174 27789 raft_consensus.cc:385] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.223197 27789 raft_consensus.cc:740] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 098a60bd14ce46f19f3e0fec7c40e61f, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.223362 27789 consensus_queue.cc:260] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [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: "098a60bd14ce46f19f3e0fec7c40e61f" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 34359 } }
I20260812 06:17:46.223446 27789 raft_consensus.cc:399] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.223472 27789 raft_consensus.cc:493] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.223547 27789 raft_consensus.cc:3060] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.224287 27789 raft_consensus.cc:515] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "098a60bd14ce46f19f3e0fec7c40e61f" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 34359 } }
I20260812 06:17:46.224433 27789 leader_election.cc:304] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [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: 098a60bd14ce46f19f3e0fec7c40e61f; no voters: 
I20260812 06:17:46.224647 27789 leader_election.cc:290] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.224766 27791 raft_consensus.cc:2804] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.224947 27791 raft_consensus.cc:697] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 1 LEADER]: Becoming Leader. State: Replica: 098a60bd14ce46f19f3e0fec7c40e61f, State: Running, Role: LEADER
I20260812 06:17:46.225061 27789 ts_tablet_manager.cc:1434] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:46.225418 27773 heartbeater.cc:499] Master 127.26.218.126:45901 was elected leader, sending a full tablet report...
I20260812 06:17:46.225149 27791 consensus_queue.cc:237] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [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: "098a60bd14ce46f19f3e0fec7c40e61f" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 34359 } }
I20260812 06:17:46.228472 27544 catalog_manager.cc:5719] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f reported cstate change: term changed from 0 to 1, leader changed from <none> to 098a60bd14ce46f19f3e0fec7c40e61f (127.26.218.65). New cstate: current_term: 1 leader_uuid: "098a60bd14ce46f19f3e0fec7c40e61f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "098a60bd14ce46f19f3e0fec7c40e61f" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 34359 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:46.301275 27497 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.027s	sys 0.001s
I20260812 06:17:46.427670 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=15.086190
I20260812 06:17:46.570822 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.143s	user 0.105s	sys 0.036s Metrics: {"bytes_written":8902491,"cfile_init":1,"compiler_manager_pool.queue_time_us":242,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":793,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36532,"lbm_writes_lt_1ms":584,"mutex_wait_us":220,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":155008,"thread_start_us":128,"threads_started":1,"update_count":1085}
I20260812 06:17:46.572067 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): free 20743880 bytes of WAL
I20260812 06:17:46.572361 27673 log_reader.cc:385] T e96484d7f9d0456fa0ff90e102b7bcb4: removed 2 log segments from log reader
I20260812 06:17:46.572420 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000001 (ops 1-6)
I20260812 06:17:46.572468 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000002 (ops 7-11)
I20260812 06:17:46.578691 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:46.579097 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): 12719217 bytes on disk
I20260812 06:17:46.579721 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.580122 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.196750
I20260812 06:17:46.595705 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4375,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:46.596771 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:46.719310 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.122s	user 0.103s	sys 0.015s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159599,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":900,"lbm_read_time_us":8606,"lbm_reads_lt_1ms":350,"lbm_write_time_us":22298,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":327,"threads_started":5,"update_count":1450}
I20260812 06:17:46.719879 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:46.764950 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.045s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17000,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.765431 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:46.779239 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.779938 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:46.924660 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.145s	user 0.118s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1165,"lbm_read_time_us":10973,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30696,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.925356 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=11.118625
I20260812 06:17:46.975255 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.050s	user 0.023s	sys 0.026s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18782,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:46.975941 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:46.992863 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.017s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.993438 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:47.158596 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.165s	user 0.113s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":149,"lbm_read_time_us":12628,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27787,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.159193 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=14.095187
I20260812 06:17:47.210676 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.051s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22509,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.211105 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:47.222399 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.222982 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:47.373716 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.151s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":12273,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32295,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:17:47.374205 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:47.417862 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.043s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12389541,"delete_count":0,"lbm_write_time_us":19190,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1510}
I20260812 06:17:47.418606 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:47.431874 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4904,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:47.432402 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:47.564195 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.132s	user 0.083s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":9945,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27798,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.564895 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:47.616931 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.052s	user 0.038s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20072,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.617445 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:47.629983 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.630501 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:47.780746 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.150s	user 0.132s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":11385,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31628,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.781456 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=11.118625
I20260812 06:17:47.835340 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.054s	user 0.028s	sys 0.025s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19346,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:47.835956 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:47.853590 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6557,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:47.854147 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:48.009227 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.155s	user 0.119s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":12555,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24048,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.009915 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:48.052178 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.042s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19233,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.052772 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:48.065490 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.065948 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:48.101884 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1470,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2258,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:48.102885 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): free 124257256 bytes of WAL
I20260812 06:17:48.103142 27673 log_reader.cc:385] T e96484d7f9d0456fa0ff90e102b7bcb4: removed 12 log segments from log reader
I20260812 06:17:48.103195 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000003 (ops 12-16)
I20260812 06:17:48.103229 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000004 (ops 17-21)
I20260812 06:17:48.103307 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000005 (ops 22-26)
I20260812 06:17:48.103358 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000006 (ops 27-31)
I20260812 06:17:48.103410 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000007 (ops 32-36)
I20260812 06:17:48.103467 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000008 (ops 37-41)
I20260812 06:17:48.103513 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000009 (ops 42-46)
I20260812 06:17:48.103579 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000010 (ops 47-50)
I20260812 06:17:48.103629 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000011 (ops 51-55)
I20260812 06:17:48.103677 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000012 (ops 56-60)
I20260812 06:17:48.103722 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000013 (ops 61-65)
I20260812 06:17:48.103768 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000014 (ops 66-70)
I20260812 06:17:48.134219 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:48.134825 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): 485 bytes on disk
I20260812 06:17:48.135480 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.135967 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=6.157687
I20260812 06:17:48.174217 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.038s	user 0.013s	sys 0.015s Metrics: {"bytes_written":8164053,"delete_count":0,"lbm_write_time_us":10450,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":995}
I20260812 06:17:48.174888 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:48.394483 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.219s	user 0.149s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836196,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":3429,"lbm_read_time_us":17246,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38479,"lbm_writes_lt_1ms":642,"mutex_wait_us":3045,"peak_mem_usage":75501437,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":90,"threads_started":1,"update_count":2995}
I20260812 06:17:48.395502 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=15.087375
I20260812 06:17:48.526418 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.130s	user 0.053s	sys 0.055s Metrics: {"bytes_written":16861175,"delete_count":0,"lbm_write_time_us":42306,"lbm_writes_lt_1ms":414,"reinsert_count":0,"update_count":2055}
I20260812 06:17:48.527441 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=6.157687
I20260812 06:17:48.572790 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":20117,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:48.573473 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:48.830369 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.257s	user 0.180s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918133,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":27162,"lbm_reads_lt_1ms":665,"lbm_write_time_us":42832,"lbm_writes_lt_1ms":644,"mutex_wait_us":78,"peak_mem_usage":75583507,"reinsert_count":0,"spinlock_wait_cycles":36096,"update_count":3005}
I20260812 06:17:48.831075 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=15.087375
I20260812 06:17:48.883227 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.052s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22934,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:48.883976 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:48.900030 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5794,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.900619 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:49.101867 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.201s	user 0.107s	sys 0.088s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"dirs.run_cpu_time_us":498,"dirs.run_wall_time_us":2689,"lbm_read_time_us":15035,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36063,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:17:49.102787 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=15.087375
I20260812 06:17:49.167013 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.064s	user 0.041s	sys 0.022s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23174,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:49.167779 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:49.190001 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6024,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.190536 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:49.201195 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.201818 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:49.409225 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.207s	user 0.133s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":632,"lbm_read_time_us":15096,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35463,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:49.409869 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=11.118625
I20260812 06:17:49.458469 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22111,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:49.458979 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:49.469487 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.469934 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:49.625598 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.155s	user 0.087s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":12957,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27796,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":790144,"update_count":2000}
I20260812 06:17:49.626312 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:49.671989 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.046s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17985,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.672585 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:49.688444 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.016s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.689067 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:49.824535 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.135s	user 0.086s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":10105,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26135,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:17:49.825340 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:49.874764 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.049s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.875411 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:49.887406 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.888118 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:49.924866 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.037s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1460,"drs_written":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1955,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:49.925685 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): free 133477394 bytes of WAL
I20260812 06:17:49.925967 27673 log_reader.cc:385] T e96484d7f9d0456fa0ff90e102b7bcb4: removed 13 log segments from log reader
I20260812 06:17:49.926151 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000015 (ops 71-75)
I20260812 06:17:49.926316 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000016 (ops 76-80)
I20260812 06:17:49.926375 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000017 (ops 81-85)
I20260812 06:17:49.926424 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000018 (ops 86-90)
I20260812 06:17:49.926468 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000019 (ops 91-95)
I20260812 06:17:49.926515 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000020 (ops 96-100)
I20260812 06:17:49.926558 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000021 (ops 101-105)
I20260812 06:17:49.926600 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000022 (ops 106-110)
I20260812 06:17:49.926644 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000023 (ops 111-115)
I20260812 06:17:49.926688 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000024 (ops 116-120)
I20260812 06:17:49.926731 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000025 (ops 121-125)
I20260812 06:17:49.926774 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000026 (ops 126-130)
I20260812 06:17:49.926817 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000027 (ops 131-135)
I20260812 06:17:49.960009 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.034s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:17:49.960417 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=6.157687
I20260812 06:17:49.994482 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.034s	user 0.018s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":15031,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:49.995173 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): 483 bytes on disk
I20260812 06:17:49.996174 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.997347 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:50.202898 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.205s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":218,"lbm_read_time_us":20200,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":668,"lbm_write_time_us":40599,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:50.203944 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=14.095187
I20260812 06:17:50.261264 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.057s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26490,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:50.261822 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:50.277596 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.278105 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:50.442853 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.165s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1392,"lbm_read_time_us":13375,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32919,"lbm_writes_lt_1ms":543,"mutex_wait_us":380,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:50.443437 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=14.095187
I20260812 06:17:50.507385 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.064s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.507853 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:50.520215 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.520695 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:50.673645 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.153s	user 0.112s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":12537,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31717,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:50.674331 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:50.715934 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.041s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.716591 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:50.728538 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.729125 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:50.881105 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.152s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":12958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30996,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38656,"update_count":2000}
I20260812 06:17:50.881880 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:50.937302 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.055s	user 0.023s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19747,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.937857 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:50.949276 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.949765 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.125144 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.175s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":544,"lbm_read_time_us":13778,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30922,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:17:51.126339 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:51.169099 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.169708 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:51.183188 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.183670 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.327843 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.144s	user 0.118s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":544,"lbm_read_time_us":11834,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30039,"lbm_writes_lt_1ms":443,"mutex_wait_us":364,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:51.328661 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=10.126437
I20260812 06:17:51.374044 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.045s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20744,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.374663 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=2.188937
I20260812 06:17:51.391085 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.391728 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.422940 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushMRSOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1507,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1736,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:51.423691 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): free 112692665 bytes of WAL
I20260812 06:17:51.423941 27673 log_reader.cc:385] T e96484d7f9d0456fa0ff90e102b7bcb4: removed 11 log segments from log reader
I20260812 06:17:51.423995 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000028 (ops 136-140)
I20260812 06:17:51.424028 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000029 (ops 141-145)
I20260812 06:17:51.424050 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000030 (ops 146-150)
I20260812 06:17:51.424117 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000031 (ops 151-155)
I20260812 06:17:51.424170 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000032 (ops 156-160)
I20260812 06:17:51.424222 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000033 (ops 161-165)
I20260812 06:17:51.424273 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000034 (ops 166-170)
I20260812 06:17:51.424343 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000035 (ops 171-175)
I20260812 06:17:51.424396 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000036 (ops 176-180)
I20260812 06:17:51.424445 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000037 (ops 181-185)
I20260812 06:17:51.424501 27673 log.cc:1079] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/e96484d7f9d0456fa0ff90e102b7bcb4/wal-000000038 (ops 186-190)
I20260812 06:17:51.453207 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: LogGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:51.453928 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=5.165500
I20260812 06:17:51.475643 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.021s	user 0.011s	sys 0.009s Metrics: {"bytes_written":6400017,"delete_count":0,"lbm_write_time_us":9003,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:17:51.476322 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4): 447 bytes on disk
I20260812 06:17:51.477043 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: UndoDeltaBlockGCOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.478083 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.488528 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":3176,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:17:51.489184 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.651067 27497 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.350s	user 1.892s	sys 0.156s
I20260812 06:17:51.674959 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.186s	user 0.141s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877285,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14568,"lbm_reads_lt_1ms":662,"lbm_write_time_us":39603,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:17:51.675593 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=14.095187
I20260812 06:17:51.716799 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: FlushDeltaMemStoresOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.041s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19580,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.717434 27774 maintenance_manager.cc:419] P 098a60bd14ce46f19f3e0fec7c40e61f: Scheduling MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4): perf score=1.000000
I20260812 06:17:51.742954 27497 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.091s	user 0.001s	sys 0.003s
I20260812 06:17:51.743636 27497 tablet_server.cc:179] TabletServer@127.26.218.65:0 shutting down...
I20260812 06:17:51.844738 27673 maintenance_manager.cc:643] P 098a60bd14ce46f19f3e0fec7c40e61f: MajorDeltaCompactionOp(e96484d7f9d0456fa0ff90e102b7bcb4) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1413,"lbm_read_time_us":10343,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24412,"lbm_writes_lt_1ms":443,"mutex_wait_us":244,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.845799 27497 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:51.846204 27497 tablet_replica.cc:333] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f: stopping tablet replica
I20260812 06:17:51.846531 27497 raft_consensus.cc:2243] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:51.846794 27497 raft_consensus.cc:2272] T e96484d7f9d0456fa0ff90e102b7bcb4 P 098a60bd14ce46f19f3e0fec7c40e61f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:51.862502 27497 tablet_server.cc:196] TabletServer@127.26.218.65:0 shutdown complete.
I20260812 06:17:51.885485 27497 master.cc:562] Master@127.26.218.126:45901 shutting down...
I20260812 06:17:51.889955 27497 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:51.890172 27497 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:51.890288 27497 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8d06df284010483887c200ce516ef2ab: stopping tablet replica
I20260812 06:17:51.902993 27497 master.cc:584] Master@127.26.218.126:45901 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5961 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:52.000771 27497 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.26.218.126:38275
I20260812 06:17:52.001180 27497 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.003396 27832 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:17:52.003553 27828 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:17:52.003701 27829 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:17:52.003777 27497 server_base.cc:1061] running on GCE node
I20260812 06:17:52.003957 27497 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.004030 27497 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:17:52.004065 27497 hybrid_clock.cc:648] HybridClock initialized: now 1786515472004064 us; error 0 us; skew 500 ppm
I20260812 06:17:52.005122 27497 webserver.cc:533] Webserver started at http://127.26.218.126:34421/ using document root <none> and password file <none>
I20260812 06:17:52.005326 27497 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.005401 27497 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.005488 27497 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.005995 27497 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/master-0-root/instance:
uuid: "285014f13259446ab6819b10f6056314"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-7nm7"
I20260812 06:17:52.007699 27497 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:52.008720 27846 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:17:52.009025 27497 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:52.009150 27497 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/master-0-root
uuid: "285014f13259446ab6819b10f6056314"
format_stamp: "Formatted at 2026-08-12 06:17:51 on dist-test-slave-7nm7"
I20260812 06:17:52.009277 27497 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-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:17:52.020117 27497 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.020561 27497 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.025087 27497 rpc_server.cc:307] RPC server started. Bound to: 127.26.218.126:38275
I20260812 06:17:52.033704 27937 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:17:52.040932 27936 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.218.126:38275 every 8 connection(s)
I20260812 06:17:52.041491 27937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314: Bootstrap starting.
I20260812 06:17:52.042333 27937 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.043368 27937 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314: No bootstrap required, opened a new log
I20260812 06:17:52.043731 27937 raft_consensus.cc:359] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "285014f13259446ab6819b10f6056314" member_type: VOTER }
I20260812 06:17:52.043816 27937 raft_consensus.cc:385] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.043838 27937 raft_consensus.cc:740] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 285014f13259446ab6819b10f6056314, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.043942 27937 consensus_queue.cc:260] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [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: "285014f13259446ab6819b10f6056314" member_type: VOTER }
I20260812 06:17:52.043998 27937 raft_consensus.cc:399] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.044020 27937 raft_consensus.cc:493] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.044049 27937 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.044744 27937 raft_consensus.cc:515] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "285014f13259446ab6819b10f6056314" member_type: VOTER }
I20260812 06:17:52.044860 27937 leader_election.cc:304] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [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: 285014f13259446ab6819b10f6056314; no voters: 
I20260812 06:17:52.045015 27937 leader_election.cc:290] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.045182 27940 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.045382 27940 raft_consensus.cc:697] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 1 LEADER]: Becoming Leader. State: Replica: 285014f13259446ab6819b10f6056314, State: Running, Role: LEADER
I20260812 06:17:52.045529 27937 sys_catalog.cc:565] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:52.045543 27940 consensus_queue.cc:237] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [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: "285014f13259446ab6819b10f6056314" member_type: VOTER }
I20260812 06:17:52.046031 27942 sys_catalog.cc:455] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 285014f13259446ab6819b10f6056314. Latest consensus state: current_term: 1 leader_uuid: "285014f13259446ab6819b10f6056314" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "285014f13259446ab6819b10f6056314" member_type: VOTER } }
I20260812 06:17:52.046005 27941 sys_catalog.cc:455] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "285014f13259446ab6819b10f6056314" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "285014f13259446ab6819b10f6056314" member_type: VOTER } }
I20260812 06:17:52.046108 27942 sys_catalog.cc:458] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.046118 27941 sys_catalog.cc:458] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:52.046798 27948 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:52.047475 27948 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:52.047715 27497 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:52.049423 27948 catalog_manager.cc:1383] Generated new cluster ID: 6049469a5a194a0a879a12adfdc9428d
I20260812 06:17:52.049489 27948 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:52.098351 27948 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:52.098955 27948 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:52.105399 27948 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314: Generated new TSK 0
I20260812 06:17:52.105571 27948 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:52.112355 27497 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:52.114426 27970 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:17:52.114468 27976 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:17:52.114470 27973 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:17:52.114693 27497 server_base.cc:1061] running on GCE node
I20260812 06:17:52.114823 27497 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:52.114856 27497 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:17:52.114871 27497 hybrid_clock.cc:648] HybridClock initialized: now 1786515472114871 us; error 0 us; skew 500 ppm
I20260812 06:17:52.115717 27497 webserver.cc:533] Webserver started at http://127.26.218.65:45523/ using document root <none> and password file <none>
I20260812 06:17:52.115847 27497 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:52.115890 27497 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:52.115944 27497 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:52.116312 27497 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/instance:
uuid: "238a0cd37d9741b382f8aedf9b51ed29"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-7nm7"
I20260812 06:17:52.117801 27497 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:52.118904 27984 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:17:52.119200 27497 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:52.119295 27497 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root
uuid: "238a0cd37d9741b382f8aedf9b51ed29"
format_stamp: "Formatted at 2026-08-12 06:17:52 on dist-test-slave-7nm7"
I20260812 06:17:52.119386 27497 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-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:17:52.131961 27497 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:52.132428 27497 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:52.132831 27497 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:52.133363 27497 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:52.133428 27497 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.133491 27497 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:52.133548 27497 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:52.138566 27497 rpc_server.cc:307] RPC server started. Bound to: 127.26.218.65:42117
I20260812 06:17:52.138787 28106 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.26.218.65:42117 every 8 connection(s)
I20260812 06:17:52.148751 28107 heartbeater.cc:344] Connected to a master server at 127.26.218.126:38275
I20260812 06:17:52.148885 28107 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:52.149174 28107 heartbeater.cc:507] Master 127.26.218.126:38275 requested a full tablet report, sending...
I20260812 06:17:52.149892 27876 ts_manager.cc:194] Registered new tserver with Master: 238a0cd37d9741b382f8aedf9b51ed29 (127.26.218.65:42117)
I20260812 06:17:52.150321 27497 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011247237s
I20260812 06:17:52.150847 27876 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47262
I20260812 06:17:52.158517 27876 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47274:
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:17:52.168284 28033 tablet_service.cc:1511] Processing CreateTablet for tablet 094f4f9ab18d4c6a82d49417276180eb (DEFAULT_TABLE table=heavy-update-compaction-test [id=896566b6eb2e4ea28a11cd69e07a01c3]), partition=
I20260812 06:17:52.168604 28033 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 094f4f9ab18d4c6a82d49417276180eb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:52.170761 28123 tablet_bootstrap.cc:492] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Bootstrap starting.
I20260812 06:17:52.171653 28123 tablet_bootstrap.cc:654] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:52.172816 28123 tablet_bootstrap.cc:492] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: No bootstrap required, opened a new log
I20260812 06:17:52.172940 28123 ts_tablet_manager.cc:1403] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:52.173700 28123 raft_consensus.cc:359] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "238a0cd37d9741b382f8aedf9b51ed29" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 42117 } }
I20260812 06:17:52.173825 28123 raft_consensus.cc:385] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:52.173882 28123 raft_consensus.cc:740] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 238a0cd37d9741b382f8aedf9b51ed29, State: Initialized, Role: FOLLOWER
I20260812 06:17:52.174042 28123 consensus_queue.cc:260] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [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: "238a0cd37d9741b382f8aedf9b51ed29" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 42117 } }
I20260812 06:17:52.174163 28123 raft_consensus.cc:399] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:52.174219 28123 raft_consensus.cc:493] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:52.174299 28123 raft_consensus.cc:3060] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:52.175079 28123 raft_consensus.cc:515] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "238a0cd37d9741b382f8aedf9b51ed29" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 42117 } }
I20260812 06:17:52.175251 28123 leader_election.cc:304] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [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: 238a0cd37d9741b382f8aedf9b51ed29; no voters: 
I20260812 06:17:52.175524 28123 leader_election.cc:290] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:52.175655 28125 raft_consensus.cc:2804] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:52.175907 28123 ts_tablet_manager.cc:1434] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:52.175918 28107 heartbeater.cc:499] Master 127.26.218.126:38275 was elected leader, sending a full tablet report...
I20260812 06:17:52.175921 28125 raft_consensus.cc:697] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 1 LEADER]: Becoming Leader. State: Replica: 238a0cd37d9741b382f8aedf9b51ed29, State: Running, Role: LEADER
I20260812 06:17:52.176218 28125 consensus_queue.cc:237] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [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: "238a0cd37d9741b382f8aedf9b51ed29" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 42117 } }
I20260812 06:17:52.177752 27876 catalog_manager.cc:5719] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 reported cstate change: term changed from 0 to 1, leader changed from <none> to 238a0cd37d9741b382f8aedf9b51ed29 (127.26.218.65). New cstate: current_term: 1 leader_uuid: "238a0cd37d9741b382f8aedf9b51ed29" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "238a0cd37d9741b382f8aedf9b51ed29" member_type: VOTER last_known_addr { host: "127.26.218.65" port: 42117 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:52.242012 27497 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.017s	sys 0.006s
I20260812 06:17:52.389680 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb): perf score=19.054940
I20260812 06:17:52.560501 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.171s	user 0.125s	sys 0.040s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":723,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44716,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:52.561393 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling LogGCOp(094f4f9ab18d4c6a82d49417276180eb): free 20743880 bytes of WAL
I20260812 06:17:52.561690 27993 log_reader.cc:385] T 094f4f9ab18d4c6a82d49417276180eb: removed 2 log segments from log reader
I20260812 06:17:52.561769 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000001 (ops 1-6)
I20260812 06:17:52.561825 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000002 (ops 7-11)
I20260812 06:17:52.566584 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: LogGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:52.566967 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:52.585325 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.018s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.585919 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:52.769899 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.184s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":698,"lbm_read_time_us":13189,"lbm_reads_lt_1ms":468,"lbm_write_time_us":29817,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":329,"threads_started":5,"update_count":2000}
I20260812 06:17:52.770624 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:52.821233 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.050s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22744,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.821693 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:52.985405 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.164s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":820,"lbm_read_time_us":11943,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28516,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:52.986061 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb): 16411392 bytes on disk
I20260812 06:17:52.986656 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.987116 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=11.118625
I20260812 06:17:53.023878 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.037s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16364,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:53.024382 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.043262 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5100,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.043802 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:53.179056 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.135s	user 0.103s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":10993,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26285,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.179966 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=10.126437
I20260812 06:17:53.224368 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.044s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.224906 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.250874 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.026s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":6037,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:17:53.251412 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.267161 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":6103,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:53.267721 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:53.434367 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.166s	user 0.128s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1030,"lbm_read_time_us":14938,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33433,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2500}
I20260812 06:17:53.434959 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=11.118625
I20260812 06:17:53.470532 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.035s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15342,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:53.471413 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.485373 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.485812 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:53.620494 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.135s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":130,"lbm_read_time_us":11340,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25549,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:53.621070 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=10.126437
I20260812 06:17:53.674916 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.053s	user 0.026s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18041,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.675508 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.686676 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.687127 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:53.850906 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.164s	user 0.100s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":650,"lbm_read_time_us":12370,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27672,"lbm_writes_lt_1ms":443,"mutex_wait_us":344,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:53.853645 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=10.126437
I20260812 06:17:53.896034 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.040s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16728,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:53.896667 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.907859 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.908357 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:53.936818 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1214,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1542,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:53.937409 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling LogGCOp(094f4f9ab18d4c6a82d49417276180eb): free 112239265 bytes of WAL
I20260812 06:17:53.937624 27993 log_reader.cc:385] T 094f4f9ab18d4c6a82d49417276180eb: removed 11 log segments from log reader
I20260812 06:17:53.937669 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000003 (ops 12-16)
I20260812 06:17:53.937700 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000004 (ops 17-21)
I20260812 06:17:53.937764 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000005 (ops 22-26)
I20260812 06:17:53.937810 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000006 (ops 27-31)
I20260812 06:17:53.937855 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000007 (ops 32-36)
I20260812 06:17:53.937896 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000008 (ops 37-40)
I20260812 06:17:53.937932 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000009 (ops 41-45)
I20260812 06:17:53.937978 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000010 (ops 46-50)
I20260812 06:17:53.938023 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000011 (ops 51-55)
I20260812 06:17:53.938063 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000012 (ops 56-60)
I20260812 06:17:53.938103 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000013 (ops 61-65)
I20260812 06:17:53.965906 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: LogGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:53.966361 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:53.998185 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.032s	user 0.002s	sys 0.022s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":6775,"lbm_writes_lt_1ms":106,"mutex_wait_us":46,"reinsert_count":0,"update_count":515}
I20260812 06:17:53.998726 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:54.009229 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:54.009714 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb): 463 bytes on disk
I20260812 06:17:54.010111 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.010596 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:54.234170 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.223s	user 0.139s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":443,"lbm_read_time_us":16700,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37555,"lbm_writes_lt_1ms":643,"mutex_wait_us":127,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:54.235280 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:54.300666 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.063s	user 0.022s	sys 0.038s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":25829,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.301353 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:54.322134 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.322656 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:54.514385 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.192s	user 0.125s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":741,"lbm_read_time_us":13650,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33060,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:54.515045 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=15.087375
I20260812 06:17:54.568140 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.053s	user 0.042s	sys 0.009s Metrics: {"bytes_written":16820117,"delete_count":0,"lbm_write_time_us":22564,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:54.577418 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:54.592562 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4959,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.593004 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:54.777403 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.184s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774650,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":12334,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30760,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:54.778085 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:54.827759 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.049s	user 0.021s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22423,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.828204 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:54.862905 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.035s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.863535 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:54.875424 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.876068 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:55.076316 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.200s	user 0.133s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":878,"lbm_read_time_us":14738,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34972,"lbm_writes_lt_1ms":643,"mutex_wait_us":432,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:17:55.077106 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=15.087375
I20260812 06:17:55.138816 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.061s	user 0.042s	sys 0.019s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22110,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:55.139325 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:55.151263 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:55.151783 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:55.343600 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.192s	user 0.138s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1029,"lbm_read_time_us":14810,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30040,"lbm_writes_lt_1ms":543,"mutex_wait_us":425,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:17:55.347995 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=15.087375
I20260812 06:17:55.403349 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.055s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16573998,"delete_count":0,"lbm_write_time_us":18526,"lbm_writes_lt_1ms":407,"reinsert_count":0,"update_count":2020}
I20260812 06:17:55.403870 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=3.181125
I20260812 06:17:55.417862 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4348810,"delete_count":0,"lbm_write_time_us":5545,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:55.418376 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:55.456704 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.038s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1346,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2233,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:55.457401 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling LogGCOp(094f4f9ab18d4c6a82d49417276180eb): free 120553390 bytes of WAL
I20260812 06:17:55.457652 27993 log_reader.cc:385] T 094f4f9ab18d4c6a82d49417276180eb: removed 12 log segments from log reader
I20260812 06:17:55.457722 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000014 (ops 66-70)
I20260812 06:17:55.457777 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000015 (ops 71-75)
I20260812 06:17:55.457834 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000016 (ops 76-80)
I20260812 06:17:55.457873 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000017 (ops 81-85)
I20260812 06:17:55.457911 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000018 (ops 86-90)
I20260812 06:17:55.457947 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000019 (ops 91-95)
I20260812 06:17:55.457993 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000020 (ops 96-100)
I20260812 06:17:55.458029 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000021 (ops 101-104)
I20260812 06:17:55.458072 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000022 (ops 105-109)
I20260812 06:17:55.458110 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000023 (ops 110-114)
I20260812 06:17:55.458148 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000024 (ops 115-118)
I20260812 06:17:55.458184 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000025 (ops 119-123)
I20260812 06:17:55.485795 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: LogGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:55.486503 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb): 462 bytes on disk
I20260812 06:17:55.487052 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:55.487643 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=6.157687
I20260812 06:17:55.516413 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.029s	user 0.017s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9775,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:55.517158 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:55.758899 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.242s	user 0.126s	sys 0.111s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979638,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":546,"lbm_read_time_us":18676,"lbm_reads_lt_1ms":765,"lbm_write_time_us":40799,"lbm_writes_lt_1ms":743,"mutex_wait_us":84,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:55.761490 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=18.063937
I20260812 06:17:55.827682 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.064s	user 0.023s	sys 0.039s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29288,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:55.828186 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:55.853382 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.025s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.853886 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:55.869625 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:55.870424 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:56.095767 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.225s	user 0.142s	sys 0.071s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":708,"lbm_read_time_us":15523,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42654,"lbm_writes_lt_1ms":743,"mutex_wait_us":357,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3500}
I20260812 06:17:56.096355 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=18.063937
I20260812 06:17:56.149427 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.053s	user 0.030s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":22843,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:56.149881 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:56.160820 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.161235 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:56.326480 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.165s	user 0.137s	sys 0.028s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":12849,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35804,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:17:56.327226 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:56.373139 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20844,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.373783 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:56.389971 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.390465 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:56.574446 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.184s	user 0.123s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1078,"lbm_read_time_us":13705,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35408,"lbm_writes_lt_1ms":543,"mutex_wait_us":389,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2500}
I20260812 06:17:56.575145 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:56.620697 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.045s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20028,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.621182 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:56.770640 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.149s	user 0.102s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":680,"lbm_read_time_us":9662,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25231,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:56.771370 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=11.118625
I20260812 06:17:56.807224 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":15977,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:56.808108 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:56.824777 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.825417 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:56.955626 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.130s	user 0.106s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":9452,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24984,"lbm_writes_lt_1ms":443,"mutex_wait_us":337,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:17:56.956446 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=10.126437
I20260812 06:17:56.991551 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16096,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.992311 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:57.006892 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.007382 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:57.043057 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushMRSOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.035s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":112,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1478,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2267,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:57.044082 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling LogGCOp(094f4f9ab18d4c6a82d49417276180eb): free 133024631 bytes of WAL
I20260812 06:17:57.044375 27993 log_reader.cc:385] T 094f4f9ab18d4c6a82d49417276180eb: removed 13 log segments from log reader
I20260812 06:17:57.044454 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000026 (ops 124-128)
I20260812 06:17:57.044523 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000027 (ops 129-132)
I20260812 06:17:57.044565 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000028 (ops 133-137)
I20260812 06:17:57.044605 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000029 (ops 138-142)
I20260812 06:17:57.044631 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000030 (ops 143-147)
I20260812 06:17:57.044667 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000031 (ops 148-152)
I20260812 06:17:57.044703 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000032 (ops 153-157)
I20260812 06:17:57.044757 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000033 (ops 158-162)
I20260812 06:17:57.044795 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000034 (ops 163-167)
I20260812 06:17:57.044832 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000035 (ops 168-172)
I20260812 06:17:57.044869 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000036 (ops 173-177)
I20260812 06:17:57.044905 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000037 (ops 178-182)
I20260812 06:17:57.044942 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000038 (ops 183-187)
I20260812 06:17:57.078259 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: LogGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:17:57.078962 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=6.157687
I20260812 06:17:57.108500 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.029s	user 0.016s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12870,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:57.109020 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling LogGCOp(094f4f9ab18d4c6a82d49417276180eb): free 12018004 bytes of WAL
I20260812 06:17:57.109227 27993 log_reader.cc:385] T 094f4f9ab18d4c6a82d49417276180eb: removed 1 log segments from log reader
I20260812 06:17:57.109282 27993 log.cc:1079] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: Deleting log segment in path: /tmp/dist-test-taskVf8oX0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515466028991-27497-0/minicluster-data/ts-0-root/wals/094f4f9ab18d4c6a82d49417276180eb/wal-000000039 (ops 188-192)
I20260812 06:17:57.112654 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: LogGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:57.113131 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb): perf score=1.000000
I20260812 06:17:57.285597 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: MajorDeltaCompactionOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.172s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":666,"lbm_read_time_us":12928,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35751,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:17:57.286291 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=14.095187
I20260812 06:17:57.302554 27497 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.060s	user 1.885s	sys 0.150s
I20260812 06:17:57.332147 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.046s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20240,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:57.332834 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb): 493 bytes on disk
I20260812 06:17:57.333348 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: UndoDeltaBlockGCOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:17:57.334033 27497 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.031s	user 0.001s	sys 0.000s
I20260812 06:17:57.334177 28109 maintenance_manager.cc:419] P 238a0cd37d9741b382f8aedf9b51ed29: Scheduling FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb): perf score=2.188937
I20260812 06:17:57.334546 27497 tablet_server.cc:179] TabletServer@127.26.218.65:0 shutting down...
I20260812 06:17:57.346814 27993 maintenance_manager.cc:643] P 238a0cd37d9741b382f8aedf9b51ed29: FlushDeltaMemStoresOp(094f4f9ab18d4c6a82d49417276180eb) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.347450 27497 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:57.347682 27497 tablet_replica.cc:333] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29: stopping tablet replica
I20260812 06:17:57.347821 27497 raft_consensus.cc:2243] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.348008 27497 raft_consensus.cc:2272] T 094f4f9ab18d4c6a82d49417276180eb P 238a0cd37d9741b382f8aedf9b51ed29 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.351337 27497 tablet_server.cc:196] TabletServer@127.26.218.65:0 shutdown complete.
I20260812 06:17:57.354022 27497 master.cc:562] Master@127.26.218.126:38275 shutting down...
I20260812 06:17:57.357545 27497 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:57.357715 27497 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:57.357797 27497 tablet_replica.cc:333] T 00000000000000000000000000000000 P 285014f13259446ab6819b10f6056314: stopping tablet replica
I20260812 06:17:57.370469 27497 master.cc:584] Master@127.26.218.126:38275 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5466 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11429 ms total)

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