[==========] 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:28.236838 28595 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.236.254:43435
I20260812 06:17:28.237758 28595 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:28.238291 28595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.244524 28603 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:28.244620 28601 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:28.244710 28595 server_base.cc:1061] running on GCE node
W20260812 06:17:28.244917 28600 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:28.245411 28595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.245529 28595 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:28.245572 28595 hybrid_clock.cc:648] HybridClock initialized: now 1786515448245570 us; error 0 us; skew 500 ppm
I20260812 06:17:28.247243 28595 webserver.cc:533] Webserver started at http://127.27.236.254:32885/ using document root <none> and password file <none>
I20260812 06:17:28.247776 28595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.247864 28595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.248123 28595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.249682 28595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/master-0-root/instance:
uuid: "ce7dc6f9c903449e9d6522f7536b946b"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-zkpd"
I20260812 06:17:28.253060 28595 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:28.255110 28608 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:28.256098 28595 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:28.256222 28595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/master-0-root
uuid: "ce7dc6f9c903449e9d6522f7536b946b"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-zkpd"
I20260812 06:17:28.256323 28595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-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:28.271234 28595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.271852 28595 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:28.272056 28595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.279989 28595 rpc_server.cc:307] RPC server started. Bound to: 127.27.236.254:43435
I20260812 06:17:28.280040 28664 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.236.254:43435 every 8 connection(s)
I20260812 06:17:28.282194 28665 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:28.287310 28665 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: Bootstrap starting.
I20260812 06:17:28.289548 28665 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.290359 28665 log.cc:826] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:28.291926 28665 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: No bootstrap required, opened a new log
I20260812 06:17:28.294567 28665 raft_consensus.cc:359] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER }
I20260812 06:17:28.294720 28665 raft_consensus.cc:385] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.294759 28665 raft_consensus.cc:740] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ce7dc6f9c903449e9d6522f7536b946b, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.295375 28665 consensus_queue.cc:260] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [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: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER }
I20260812 06:17:28.295516 28665 raft_consensus.cc:399] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.295563 28665 raft_consensus.cc:493] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.295647 28665 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.296367 28665 raft_consensus.cc:515] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER }
I20260812 06:17:28.296741 28665 leader_election.cc:304] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [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: ce7dc6f9c903449e9d6522f7536b946b; no voters: 
I20260812 06:17:28.296989 28665 leader_election.cc:290] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.297197 28668 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.297487 28668 raft_consensus.cc:697] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 1 LEADER]: Becoming Leader. State: Replica: ce7dc6f9c903449e9d6522f7536b946b, State: Running, Role: LEADER
I20260812 06:17:28.297868 28668 consensus_queue.cc:237] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [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: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER }
I20260812 06:17:28.297941 28665 sys_catalog.cc:565] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:28.300076 28669 sys_catalog.cc:455] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ce7dc6f9c903449e9d6522f7536b946b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER } }
I20260812 06:17:28.300197 28669 sys_catalog.cc:458] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.300410 28670 sys_catalog.cc:455] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [sys.catalog]: SysCatalogTable state changed. Reason: New leader ce7dc6f9c903449e9d6522f7536b946b. Latest consensus state: current_term: 1 leader_uuid: "ce7dc6f9c903449e9d6522f7536b946b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7dc6f9c903449e9d6522f7536b946b" member_type: VOTER } }
I20260812 06:17:28.300484 28670 sys_catalog.cc:458] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.300571 28595 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:28.302332 28683 catalog_manager.cc:1594] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:28.302392 28683 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:28.302475 28684 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:28.303192 28684 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:28.307816 28684 catalog_manager.cc:1383] Generated new cluster ID: 01e25e0b63ae4da589193deccc3b5902
I20260812 06:17:28.307879 28684 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:28.321544 28684 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:28.322650 28684 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:28.330308 28684 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: Generated new TSK 0
I20260812 06:17:28.330987 28684 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:28.333137 28595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.336087 28690 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:28.336100 28689 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:28.336313 28692 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:28.336356 28595 server_base.cc:1061] running on GCE node
I20260812 06:17:28.336655 28595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.336737 28595 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:28.336762 28595 hybrid_clock.cc:648] HybridClock initialized: now 1786515448336762 us; error 0 us; skew 500 ppm
I20260812 06:17:28.337661 28595 webserver.cc:533] Webserver started at http://127.27.236.193:36053/ using document root <none> and password file <none>
I20260812 06:17:28.337837 28595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.337894 28595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.337965 28595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.338380 28595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/instance:
uuid: "6c1b2be1a4644197992b23ed3fe17508"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-zkpd"
I20260812 06:17:28.340217 28595 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:28.341327 28697 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:28.341634 28595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:28.341696 28595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root
uuid: "6c1b2be1a4644197992b23ed3fe17508"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-zkpd"
I20260812 06:17:28.341804 28595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-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:28.353891 28595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.354332 28595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.354764 28595 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:28.355635 28595 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:28.355686 28595 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.355748 28595 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:28.355800 28595 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.362435 28595 rpc_server.cc:307] RPC server started. Bound to: 127.27.236.193:37431
I20260812 06:17:28.362466 28764 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.236.193:37431 every 8 connection(s)
I20260812 06:17:28.375376 28765 heartbeater.cc:344] Connected to a master server at 127.27.236.254:43435
I20260812 06:17:28.375648 28765 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:28.376185 28765 heartbeater.cc:507] Master 127.27.236.254:43435 requested a full tablet report, sending...
I20260812 06:17:28.377712 28626 ts_manager.cc:194] Registered new tserver with Master: 6c1b2be1a4644197992b23ed3fe17508 (127.27.236.193:37431)
I20260812 06:17:28.377920 28595 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014831212s
I20260812 06:17:28.379761 28626 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39472
I20260812 06:17:28.388088 28626 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39478:
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:28.403174 28728 tablet_service.cc:1511] Processing CreateTablet for tablet 9d3ef4d7981841d691452733ab518bfe (DEFAULT_TABLE table=heavy-update-compaction-test [id=3ff6eb1397774642950722badc465ebc]), partition=
I20260812 06:17:28.403661 28728 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9d3ef4d7981841d691452733ab518bfe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:28.406185 28777 tablet_bootstrap.cc:492] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Bootstrap starting.
I20260812 06:17:28.407202 28777 tablet_bootstrap.cc:654] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.408457 28777 tablet_bootstrap.cc:492] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: No bootstrap required, opened a new log
I20260812 06:17:28.408583 28777 ts_tablet_manager.cc:1403] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:28.409029 28777 raft_consensus.cc:359] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1b2be1a4644197992b23ed3fe17508" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 37431 } }
I20260812 06:17:28.409129 28777 raft_consensus.cc:385] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.409153 28777 raft_consensus.cc:740] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6c1b2be1a4644197992b23ed3fe17508, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.409348 28777 consensus_queue.cc:260] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [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: "6c1b2be1a4644197992b23ed3fe17508" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 37431 } }
I20260812 06:17:28.409447 28777 raft_consensus.cc:399] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.409510 28777 raft_consensus.cc:493] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.409567 28777 raft_consensus.cc:3060] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.410553 28777 raft_consensus.cc:515] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1b2be1a4644197992b23ed3fe17508" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 37431 } }
I20260812 06:17:28.410710 28777 leader_election.cc:304] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [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: 6c1b2be1a4644197992b23ed3fe17508; no voters: 
I20260812 06:17:28.410940 28777 leader_election.cc:290] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.411056 28779 raft_consensus.cc:2804] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.411319 28777 ts_tablet_manager.cc:1434] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:28.411330 28779 raft_consensus.cc:697] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 1 LEADER]: Becoming Leader. State: Replica: 6c1b2be1a4644197992b23ed3fe17508, State: Running, Role: LEADER
I20260812 06:17:28.411613 28765 heartbeater.cc:499] Master 127.27.236.254:43435 was elected leader, sending a full tablet report...
I20260812 06:17:28.411562 28779 consensus_queue.cc:237] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [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: "6c1b2be1a4644197992b23ed3fe17508" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 37431 } }
I20260812 06:17:28.414300 28626 catalog_manager.cc:5719] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6c1b2be1a4644197992b23ed3fe17508 (127.27.236.193). New cstate: current_term: 1 leader_uuid: "6c1b2be1a4644197992b23ed3fe17508" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c1b2be1a4644197992b23ed3fe17508" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 37431 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:28.487325 28595 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.018s	sys 0.012s
I20260812 06:17:28.613548 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushMRSOp(9d3ef4d7981841d691452733ab518bfe): perf score=15.086190
I20260812 06:17:28.775507 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushMRSOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.162s	user 0.119s	sys 0.037s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":218,"delete_count":0,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39554,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":3840,"thread_start_us":91,"threads_started":1,"update_count":1450}
I20260812 06:17:28.776878 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 20743880 bytes of WAL
I20260812 06:17:28.777240 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 2 log segments from log reader
I20260812 06:17:28.777323 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000001 (ops 1-6)
I20260812 06:17:28.777410 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000002 (ops 7-11)
I20260812 06:17:28.783597 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:28.783953 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:28.804738 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.021s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.806245 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe): 12719216 bytes on disk
I20260812 06:17:28.806882 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.807353 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:28.844084 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.037s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.847986 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:28.860540 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3323183,"delete_count":0,"lbm_write_time_us":4669,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:28.860978 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.044574 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.183s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":605,"cfile_cache_miss_bytes":27687622,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1133,"lbm_read_time_us":13693,"lbm_reads_lt_1ms":637,"lbm_write_time_us":32331,"lbm_writes_lt_1ms":614,"mutex_wait_us":27,"peak_mem_usage":71231305,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":388,"threads_started":5,"update_count":2855}
I20260812 06:17:29.045239 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=11.118625
I20260812 06:17:29.084548 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.039s	user 0.027s	sys 0.012s Metrics: {"bytes_written":13086954,"delete_count":0,"lbm_write_time_us":16690,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:17:29.085076 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:29.100971 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.101498 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.250109 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.148s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_miss":451,"cfile_cache_miss_bytes":21451741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1279,"lbm_read_time_us":9381,"lbm_reads_lt_1ms":491,"lbm_write_time_us":25550,"lbm_writes_lt_1ms":462,"mutex_wait_us":310,"peak_mem_usage":52509377,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2095}
I20260812 06:17:29.250638 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=11.118625
I20260812 06:17:29.281503 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":12983,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.282011 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:29.297281 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5796,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.297807 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.430101 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.132s	user 0.099s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":7148,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26805,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:29.430751 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=10.126437
I20260812 06:17:29.475981 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.045s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307499,"delete_count":0,"lbm_write_time_us":15905,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.476409 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:29.486570 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.487146 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.620500 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.133s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672287,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":9588,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26080,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:17:29.621062 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=10.126437
I20260812 06:17:29.665956 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.045s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14117,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.666684 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.196750
I20260812 06:17:29.676666 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":2297558,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:17:29.677107 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.682932 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":2005,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:17:29.683303 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:29.838490 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.155s	user 0.099s	sys 0.056s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672301,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":808,"lbm_read_time_us":11823,"lbm_reads_lt_1ms":473,"lbm_write_time_us":24825,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:17:29.839144 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=10.126437
I20260812 06:17:29.888612 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.049s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18469,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.889156 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:29.904426 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.904948 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.026938 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.122s	user 0.109s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":8735,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22285,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2000}
I20260812 06:17:30.027705 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=10.126437
I20260812 06:17:30.065924 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.038s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15694,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.066426 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.076716 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.077090 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushMRSOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.110317 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushMRSOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2174,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:30.111071 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 112692387 bytes of WAL
I20260812 06:17:30.111295 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 11 log segments from log reader
I20260812 06:17:30.111356 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000003 (ops 12-17)
I20260812 06:17:30.111408 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000004 (ops 18-22)
I20260812 06:17:30.111465 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000005 (ops 23-27)
I20260812 06:17:30.111505 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000006 (ops 28-32)
I20260812 06:17:30.111543 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000007 (ops 33-37)
I20260812 06:17:30.111580 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000008 (ops 38-42)
I20260812 06:17:30.111616 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000009 (ops 43-46)
I20260812 06:17:30.111652 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000010 (ops 47-51)
I20260812 06:17:30.111689 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000011 (ops 52-56)
I20260812 06:17:30.111725 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000012 (ops 57-61)
I20260812 06:17:30.111761 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000013 (ops 62-66)
I20260812 06:17:30.137352 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:30.137733 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe): 462 bytes on disk
I20260812 06:17:30.138139 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.138599 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.152652 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":106,"mutex_wait_us":54,"reinsert_count":0,"update_count":515}
I20260812 06:17:30.153033 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 11564875 bytes of WAL
I20260812 06:17:30.153216 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 1 log segments from log reader
I20260812 06:17:30.153258 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000014 (ops 67-70)
I20260812 06:17:30.155411 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:30.155674 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.167196 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3979583,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:30.167809 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.341820 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.174s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":622,"lbm_read_time_us":12327,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36475,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:17:30.342548 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:30.391541 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.049s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18820,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.392172 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.402717 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.403162 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.549268 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.146s	user 0.104s	sys 0.035s 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":1013,"lbm_read_time_us":9324,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29051,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:17:30.549814 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=11.118625
I20260812 06:17:30.586850 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.037s	user 0.010s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15865,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:30.587523 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.607002 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4243,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.607510 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.617084 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3597,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.617509 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.770000 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.152s	user 0.124s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":295,"lbm_read_time_us":10056,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27847,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":59264,"update_count":2500}
I20260812 06:17:30.770802 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:30.821280 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.050s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21805,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.821839 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:30.833084 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.833668 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:30.995358 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.161s	user 0.119s	sys 0.039s 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":640,"lbm_read_time_us":9369,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31756,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:30.996892 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=13.103000
I20260812 06:17:31.054688 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.058s	user 0.019s	sys 0.023s Metrics: {"bytes_written":14563813,"delete_count":0,"lbm_write_time_us":21259,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":356,"reinsert_count":0,"update_count":1775}
I20260812 06:17:31.055162 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=4.173312
I20260812 06:17:31.071352 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":5948759,"delete_count":0,"lbm_write_time_us":6533,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:17:31.071805 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:31.246923 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.175s	user 0.107s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":495,"lbm_read_time_us":13759,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30799,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:31.247464 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:31.308914 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.061s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":23612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.309489 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:31.320071 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.320715 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:31.487596 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.167s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":12084,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27404,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:31.488372 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:31.553400 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.065s	user 0.040s	sys 0.024s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":26448,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.554051 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:31.564932 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.565387 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushMRSOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:31.610981 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushMRSOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.045s	user 0.041s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":138,"dirs.run_wall_time_us":1443,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2302,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:31.611737 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 121006400 bytes of WAL
I20260812 06:17:31.612008 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 12 log segments from log reader
I20260812 06:17:31.612052 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000015 (ops 71-75)
I20260812 06:17:31.612082 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000016 (ops 76-80)
I20260812 06:17:31.612149 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000017 (ops 81-84)
I20260812 06:17:31.612190 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000018 (ops 85-89)
I20260812 06:17:31.612231 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000019 (ops 90-94)
I20260812 06:17:31.612272 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000020 (ops 95-99)
I20260812 06:17:31.612320 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000021 (ops 100-104)
I20260812 06:17:31.612360 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000022 (ops 105-109)
I20260812 06:17:31.612401 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000023 (ops 110-114)
I20260812 06:17:31.612439 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000024 (ops 115-119)
I20260812 06:17:31.612478 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000025 (ops 120-124)
I20260812 06:17:31.612516 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000026 (ops 125-129)
I20260812 06:17:31.636615 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:31.637030 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe): 492 bytes on disk
I20260812 06:17:31.637470 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.637981 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:31.659337 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.021s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.659752 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:31.671865 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.672415 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:31.905274 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.232s	user 0.157s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":818,"lbm_read_time_us":16219,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39530,"lbm_writes_lt_1ms":743,"mutex_wait_us":82,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":96,"threads_started":1,"update_count":3500}
I20260812 06:17:31.906036 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=18.063937
I20260812 06:17:31.960904 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.055s	user 0.038s	sys 0.015s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":24122,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:31.961439 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:31.978292 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.978891 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:32.143446 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.164s	user 0.140s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1392,"lbm_read_time_us":12616,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32412,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":3000}
I20260812 06:17:32.144973 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:32.192523 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.047s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.193100 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:32.211030 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.211607 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:32.391466 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.180s	user 0.121s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":306,"lbm_read_time_us":10281,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32627,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.392161 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:32.443778 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.051s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21269,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.444465 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:32.594929 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.150s	user 0.083s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":999,"lbm_read_time_us":11413,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23793,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":293,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:32.595504 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:32.646348 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.051s	user 0.024s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18141,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.646894 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:32.660351 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.660805 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:32.836069 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.175s	user 0.113s	sys 0.059s 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":254,"lbm_read_time_us":12097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27364,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:32.836630 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=14.095187
I20260812 06:17:32.889045 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.052s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23446,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:32.889568 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:32.900651 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.901098 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:33.056532 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.155s	user 0.114s	sys 0.040s 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":330,"lbm_read_time_us":10601,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28745,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:17:33.057138 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=11.118625
I20260812 06:17:33.092703 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.035s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14872,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.093169 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:33.112068 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.019s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.112587 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:33.122134 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3607,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.122550 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushMRSOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:33.157191 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushMRSOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1337,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1908,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:33.157840 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 133024698 bytes of WAL
I20260812 06:17:33.158063 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 13 log segments from log reader
I20260812 06:17:33.158107 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000027 (ops 130-134)
I20260812 06:17:33.158135 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000028 (ops 135-138)
I20260812 06:17:33.158200 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000029 (ops 139-143)
I20260812 06:17:33.158252 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000030 (ops 144-148)
I20260812 06:17:33.158293 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000031 (ops 149-153)
I20260812 06:17:33.158344 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000032 (ops 154-158)
I20260812 06:17:33.158381 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000033 (ops 159-163)
I20260812 06:17:33.158422 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000034 (ops 164-168)
I20260812 06:17:33.158458 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000035 (ops 169-173)
I20260812 06:17:33.158496 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000036 (ops 174-178)
I20260812 06:17:33.158535 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000037 (ops 179-183)
I20260812 06:17:33.158574 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000038 (ops 184-188)
I20260812 06:17:33.158617 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000039 (ops 189-193)
I20260812 06:17:33.188620 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:33.188988 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe): 492 bytes on disk
I20260812 06:17:33.189450 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: UndoDeltaBlockGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.190120 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=3.181125
I20260812 06:17:33.213826 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.024s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:33.214381 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling LogGCOp(9d3ef4d7981841d691452733ab518bfe): free 12017954 bytes of WAL
I20260812 06:17:33.214666 28702 log_reader.cc:385] T 9d3ef4d7981841d691452733ab518bfe: removed 1 log segments from log reader
I20260812 06:17:33.214730 28702 log.cc:1079] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/9d3ef4d7981841d691452733ab518bfe/wal-000000040 (ops 194-198)
I20260812 06:17:33.217676 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: LogGCOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:33.218098 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe): perf score=2.188937
I20260812 06:17:33.232888 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: FlushDeltaMemStoresOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.015s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5408,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.233383 28766 maintenance_manager.cc:419] P 6c1b2be1a4644197992b23ed3fe17508: Scheduling MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe): perf score=1.000000
I20260812 06:17:33.289626 28595 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.802s	user 1.811s	sys 0.126s
I20260812 06:17:33.390334 28595 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.100s	user 0.001s	sys 0.000s
I20260812 06:17:33.390997 28595 tablet_server.cc:179] TabletServer@127.27.236.193:0 shutting down...
I20260812 06:17:33.435850 28702 maintenance_manager.cc:643] P 6c1b2be1a4644197992b23ed3fe17508: MajorDeltaCompactionOp(9d3ef4d7981841d691452733ab518bfe) complete. Timing: real 0.202s	user 0.134s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":859,"lbm_read_time_us":17625,"lbm_reads_lt_1ms":771,"lbm_write_time_us":32640,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16512,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:17:33.436655 28595 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:33.437073 28595 tablet_replica.cc:333] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508: stopping tablet replica
I20260812 06:17:33.437321 28595 raft_consensus.cc:2243] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:33.437562 28595 raft_consensus.cc:2272] T 9d3ef4d7981841d691452733ab518bfe P 6c1b2be1a4644197992b23ed3fe17508 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:33.455592 28595 tablet_server.cc:196] TabletServer@127.27.236.193:0 shutdown complete.
I20260812 06:17:33.494244 28595 master.cc:562] Master@127.27.236.254:43435 shutting down...
I20260812 06:17:33.497823 28595 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:33.497987 28595 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:33.498044 28595 tablet_replica.cc:333] T 00000000000000000000000000000000 P ce7dc6f9c903449e9d6522f7536b946b: stopping tablet replica
I20260812 06:17:33.510326 28595 master.cc:584] Master@127.27.236.254:43435 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5358 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:33.608771 28595 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.236.254:41881
I20260812 06:17:33.609217 28595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:33.611227 28799 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:33.611263 28800 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:33.611402 28595 server_base.cc:1061] running on GCE node
W20260812 06:17:33.611477 28802 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:33.611651 28595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:33.611693 28595 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:33.611709 28595 hybrid_clock.cc:648] HybridClock initialized: now 1786515453611709 us; error 0 us; skew 500 ppm
I20260812 06:17:33.612893 28595 webserver.cc:533] Webserver started at http://127.27.236.254:44227/ using document root <none> and password file <none>
I20260812 06:17:33.613032 28595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:33.613071 28595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:33.613122 28595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:33.613456 28595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/master-0-root/instance:
uuid: "6da70f01c5b841fbbe0108f08e0c3202"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-zkpd"
I20260812 06:17:33.614872 28595 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:33.615686 28809 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:33.615988 28595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:33.616080 28595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/master-0-root
uuid: "6da70f01c5b841fbbe0108f08e0c3202"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-zkpd"
I20260812 06:17:33.616165 28595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-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:33.625414 28595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:33.625772 28595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:33.629918 28595 rpc_server.cc:307] RPC server started. Bound to: 127.27.236.254:41881
I20260812 06:17:33.631654 28866 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:33.633927 28865 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.236.254:41881 every 8 connection(s)
I20260812 06:17:33.637097 28866 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202: Bootstrap starting.
I20260812 06:17:33.637876 28866 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:33.638778 28866 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202: No bootstrap required, opened a new log
I20260812 06:17:33.639181 28866 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER }
I20260812 06:17:33.639266 28866 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:33.639323 28866 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6da70f01c5b841fbbe0108f08e0c3202, State: Initialized, Role: FOLLOWER
I20260812 06:17:33.639488 28866 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [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: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER }
I20260812 06:17:33.639578 28866 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:33.639647 28866 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:33.639709 28866 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:33.640364 28866 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER }
I20260812 06:17:33.640509 28866 leader_election.cc:304] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [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: 6da70f01c5b841fbbe0108f08e0c3202; no voters: 
I20260812 06:17:33.640708 28866 leader_election.cc:290] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:33.640786 28869 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:33.641049 28869 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 1 LEADER]: Becoming Leader. State: Replica: 6da70f01c5b841fbbe0108f08e0c3202, State: Running, Role: LEADER
I20260812 06:17:33.641196 28866 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:33.641177 28869 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [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: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER }
I20260812 06:17:33.641698 28870 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6da70f01c5b841fbbe0108f08e0c3202" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER } }
I20260812 06:17:33.641734 28871 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6da70f01c5b841fbbe0108f08e0c3202. Latest consensus state: current_term: 1 leader_uuid: "6da70f01c5b841fbbe0108f08e0c3202" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6da70f01c5b841fbbe0108f08e0c3202" member_type: VOTER } }
I20260812 06:17:33.641867 28871 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:33.642139 28870 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:33.642407 28875 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:33.643190 28875 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:33.643364 28595 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:33.644948 28875 catalog_manager.cc:1383] Generated new cluster ID: b2162dd9611f4a8f87393be6183a2750
I20260812 06:17:33.645015 28875 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:33.673969 28875 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:33.674496 28875 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:33.680140 28875 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202: Generated new TSK 0
I20260812 06:17:33.680277 28875 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:33.708050 28595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:33.709897 28887 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:33.710000 28888 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:33.710143 28595 server_base.cc:1061] running on GCE node
W20260812 06:17:33.710011 28890 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:33.710379 28595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:33.710420 28595 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:33.710435 28595 hybrid_clock.cc:648] HybridClock initialized: now 1786515453710436 us; error 0 us; skew 500 ppm
I20260812 06:17:33.711273 28595 webserver.cc:533] Webserver started at http://127.27.236.193:40487/ using document root <none> and password file <none>
I20260812 06:17:33.711448 28595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:33.711504 28595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:33.711606 28595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:33.712065 28595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/instance:
uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-zkpd"
I20260812 06:17:33.713578 28595 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:33.714460 28895 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:33.714694 28595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:33.714781 28595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root
uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0"
format_stamp: "Formatted at 2026-08-12 06:17:33 on dist-test-slave-zkpd"
I20260812 06:17:33.714865 28595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-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:33.734747 28595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:33.735091 28595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:33.735380 28595 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:33.735810 28595 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:33.735873 28595 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:33.735946 28595 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:33.735996 28595 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:33.740289 28595 rpc_server.cc:307] RPC server started. Bound to: 127.27.236.193:34917
I20260812 06:17:33.740741 28967 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.236.193:34917 every 8 connection(s)
I20260812 06:17:33.748405 28968 heartbeater.cc:344] Connected to a master server at 127.27.236.254:41881
I20260812 06:17:33.748528 28968 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:33.748764 28968 heartbeater.cc:507] Master 127.27.236.254:41881 requested a full tablet report, sending...
I20260812 06:17:33.749418 28828 ts_manager.cc:194] Registered new tserver with Master: bb87c74fdbbb498eb16a0d14c0f27ab0 (127.27.236.193:34917)
I20260812 06:17:33.749814 28595 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008821235s
I20260812 06:17:33.750203 28828 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47798
I20260812 06:17:33.756582 28828 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47810:
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:33.765005 28927 tablet_service.cc:1511] Processing CreateTablet for tablet 1b50a3417c8748fdb7869356dcce1022 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9547719e80b14c158ca67d7cdfcfb1ce]), partition=
I20260812 06:17:33.765290 28927 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1b50a3417c8748fdb7869356dcce1022. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:33.767139 28982 tablet_bootstrap.cc:492] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Bootstrap starting.
I20260812 06:17:33.768136 28982 tablet_bootstrap.cc:654] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:33.769168 28982 tablet_bootstrap.cc:492] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: No bootstrap required, opened a new log
I20260812 06:17:33.769273 28982 ts_tablet_manager.cc:1403] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:33.769688 28982 raft_consensus.cc:359] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 34917 } }
I20260812 06:17:33.769796 28982 raft_consensus.cc:385] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:33.769845 28982 raft_consensus.cc:740] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb87c74fdbbb498eb16a0d14c0f27ab0, State: Initialized, Role: FOLLOWER
I20260812 06:17:33.769994 28982 consensus_queue.cc:260] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [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: "bb87c74fdbbb498eb16a0d14c0f27ab0" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 34917 } }
I20260812 06:17:33.770102 28982 raft_consensus.cc:399] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:33.770147 28982 raft_consensus.cc:493] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:33.770202 28982 raft_consensus.cc:3060] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:33.770978 28982 raft_consensus.cc:515] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 34917 } }
I20260812 06:17:33.771118 28982 leader_election.cc:304] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [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: bb87c74fdbbb498eb16a0d14c0f27ab0; no voters: 
I20260812 06:17:33.771332 28982 leader_election.cc:290] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:33.771415 28984 raft_consensus.cc:2804] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:33.771592 28984 raft_consensus.cc:697] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 1 LEADER]: Becoming Leader. State: Replica: bb87c74fdbbb498eb16a0d14c0f27ab0, State: Running, Role: LEADER
I20260812 06:17:33.771703 28968 heartbeater.cc:499] Master 127.27.236.254:41881 was elected leader, sending a full tablet report...
I20260812 06:17:33.771721 28982 ts_tablet_manager.cc:1434] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:33.771802 28984 consensus_queue.cc:237] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [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: "bb87c74fdbbb498eb16a0d14c0f27ab0" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 34917 } }
I20260812 06:17:33.773070 28828 catalog_manager.cc:5719] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 reported cstate change: term changed from 0 to 1, leader changed from <none> to bb87c74fdbbb498eb16a0d14c0f27ab0 (127.27.236.193). New cstate: current_term: 1 leader_uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb87c74fdbbb498eb16a0d14c0f27ab0" member_type: VOTER last_known_addr { host: "127.27.236.193" port: 34917 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:33.830212 28595 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.007s
I20260812 06:17:33.991406 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushMRSOp(1b50a3417c8748fdb7869356dcce1022): perf score=21.039315
I20260812 06:17:34.161623 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushMRSOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.170s	user 0.126s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":894,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43118,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:17:34.162277 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling LogGCOp(1b50a3417c8748fdb7869356dcce1022): free 20743880 bytes of WAL
I20260812 06:17:34.162513 28901 log_reader.cc:385] T 1b50a3417c8748fdb7869356dcce1022: removed 2 log segments from log reader
I20260812 06:17:34.162561 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000001 (ops 1-6)
I20260812 06:17:34.162590 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000002 (ops 7-11)
I20260812 06:17:34.167110 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: LogGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:34.167456 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022): 20513813 bytes on disk
I20260812 06:17:34.167876 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.168323 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.181733 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.182178 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:34.328385 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.146s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":10317,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23155,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":331,"threads_started":5,"update_count":2000}
I20260812 06:17:34.329034 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=11.118625
I20260812 06:17:34.377550 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.048s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15924,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.377960 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.389554 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.389973 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.399380 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3752,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.399736 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:34.589598 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.190s	user 0.112s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":218,"lbm_read_time_us":14323,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30598,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:17:34.590304 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:34.653848 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.063s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.654275 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.664605 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.664987 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:34.841266 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.176s	user 0.132s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1028,"lbm_read_time_us":12147,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30567,"lbm_writes_lt_1ms":543,"mutex_wait_us":640,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.841895 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=11.118625
I20260812 06:17:34.885154 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.043s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18637,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.885749 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.917191 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.031s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.917807 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:34.933127 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.933748 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:35.110744 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.177s	user 0.112s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":598,"lbm_read_time_us":11725,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28776,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:35.111377 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:35.159813 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.048s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21112,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.160386 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:35.183171 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.183656 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:35.357659 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.174s	user 0.107s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1145,"lbm_read_time_us":12058,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27397,"lbm_writes_lt_1ms":543,"mutex_wait_us":333,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:35.358237 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:35.415272 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.057s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22245,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.415938 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:35.427477 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.427999 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushMRSOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:35.468794 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushMRSOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.041s	user 0.018s	sys 0.020s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1460,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":2432}
I20260812 06:17:35.469578 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling LogGCOp(1b50a3417c8748fdb7869356dcce1022): free 124710236 bytes of WAL
I20260812 06:17:35.469839 28901 log_reader.cc:385] T 1b50a3417c8748fdb7869356dcce1022: removed 12 log segments from log reader
I20260812 06:17:35.469901 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000003 (ops 12-16)
I20260812 06:17:35.469987 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000004 (ops 17-21)
I20260812 06:17:35.470028 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000005 (ops 22-26)
I20260812 06:17:35.470072 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000006 (ops 27-31)
I20260812 06:17:35.470115 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000007 (ops 32-36)
I20260812 06:17:35.470155 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000008 (ops 37-41)
I20260812 06:17:35.470197 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000009 (ops 42-46)
I20260812 06:17:35.470239 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000010 (ops 47-51)
I20260812 06:17:35.470280 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000011 (ops 52-56)
I20260812 06:17:35.470319 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000012 (ops 57-61)
I20260812 06:17:35.470350 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000013 (ops 62-66)
I20260812 06:17:35.470405 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000014 (ops 67-71)
I20260812 06:17:35.498721 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: LogGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:35.499207 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022): 462 bytes on disk
I20260812 06:17:35.499759 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.500455 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:35.511786 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.512234 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:35.720230 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.208s	user 0.119s	sys 0.088s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918214,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":435,"lbm_read_time_us":13719,"lbm_reads_lt_1ms":669,"lbm_write_time_us":35270,"lbm_writes_lt_1ms":643,"mutex_wait_us":433,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:35.720885 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=15.087375
I20260812 06:17:35.783102 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.062s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21599,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:35.783829 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=4.173312
I20260812 06:17:35.801349 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":5374415,"delete_count":0,"lbm_write_time_us":7434,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:17:35.801753 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.196750
I20260812 06:17:35.808611 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":2476,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:17:35.809064 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:36.023130 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.214s	user 0.138s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":77,"lbm_read_time_us":15331,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33459,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":3000}
I20260812 06:17:36.024173 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=15.087375
I20260812 06:17:36.073969 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.049s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22607,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:36.074560 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.097350 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.023s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6079,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.097800 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.108530 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.108934 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:36.316573 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.207s	user 0.144s	sys 0.058s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":379,"lbm_read_time_us":15201,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34020,"lbm_writes_lt_1ms":643,"mutex_wait_us":73,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":3000}
I20260812 06:17:36.317435 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=16.079562
I20260812 06:17:36.370239 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.053s	user 0.035s	sys 0.012s Metrics: {"bytes_written":17681650,"delete_count":0,"lbm_write_time_us":21977,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:17:36.370934 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.386986 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":5240,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:36.387385 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.396745 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.397133 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:36.618783 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.221s	user 0.136s	sys 0.074s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1089,"lbm_read_time_us":16008,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32081,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":3000}
I20260812 06:17:36.619426 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=18.063937
I20260812 06:17:36.690362 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.071s	user 0.033s	sys 0.024s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":27487,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:36.691015 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.702510 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.703111 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:36.906951 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.202s	user 0.121s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":13448,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34947,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3000}
I20260812 06:17:36.907781 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=15.087375
I20260812 06:17:36.958593 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.051s	user 0.034s	sys 0.014s Metrics: {"bytes_written":16820147,"delete_count":0,"lbm_write_time_us":22160,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:36.959369 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.974627 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.975066 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:36.984670 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3749,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.985100 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushMRSOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:37.017570 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushMRSOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.032s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1453,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1405,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:37.018240 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling LogGCOp(1b50a3417c8748fdb7869356dcce1022): free 124710376 bytes of WAL
I20260812 06:17:37.018498 28901 log_reader.cc:385] T 1b50a3417c8748fdb7869356dcce1022: removed 12 log segments from log reader
I20260812 06:17:37.018572 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000015 (ops 72-76)
I20260812 06:17:37.018620 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000016 (ops 77-81)
I20260812 06:17:37.018654 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000017 (ops 82-86)
I20260812 06:17:37.018687 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000018 (ops 87-91)
I20260812 06:17:37.018723 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000019 (ops 92-96)
I20260812 06:17:37.018772 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000020 (ops 97-101)
I20260812 06:17:37.018810 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000021 (ops 102-106)
I20260812 06:17:37.018850 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000022 (ops 107-111)
I20260812 06:17:37.018889 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000023 (ops 112-116)
I20260812 06:17:37.018929 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000024 (ops 117-121)
I20260812 06:17:37.018967 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000025 (ops 122-126)
I20260812 06:17:37.019006 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000026 (ops 127-131)
I20260812 06:17:37.046558 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: LogGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:37.046959 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022): 483 bytes on disk
I20260812 06:17:37.047380 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022) 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:37.047875 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=3.181125
I20260812 06:17:37.062428 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4794,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:37.062829 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.072842 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.073266 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:37.317915 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.244s	user 0.158s	sys 0.087s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123257,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":287,"lbm_read_time_us":19309,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45391,"lbm_writes_lt_1ms":843,"mutex_wait_us":49,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":106,"threads_started":1,"update_count":4000}
I20260812 06:17:37.318675 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=19.056125
I20260812 06:17:37.371235 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.052s	user 0.041s	sys 0.008s Metrics: {"bytes_written":20922555,"delete_count":0,"lbm_write_time_us":22825,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:17:37.371724 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.395113 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.023s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5003,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.395557 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.410195 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.410598 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:37.607263 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.196s	user 0.125s	sys 0.072s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020614,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":201,"lbm_read_time_us":15190,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42921,"lbm_writes_lt_1ms":743,"mutex_wait_us":51,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":3500}
I20260812 06:17:37.608084 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:37.656819 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.048s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21333,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.657308 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.673573 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.016s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.674172 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:37.832980 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.159s	user 0.115s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":354,"lbm_read_time_us":10352,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30518,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:37.833663 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=11.118625
I20260812 06:17:37.869585 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.036s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15475,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:37.870200 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.898495 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.028s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5825,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:37.898952 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:37.908819 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.909269 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:38.080699 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.171s	user 0.108s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":142,"lbm_read_time_us":12626,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25524,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":75776,"update_count":2500}
I20260812 06:17:38.081396 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:38.150416 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.069s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25479,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"mutex_wait_us":1,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.151036 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:38.161791 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.162456 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:38.343560 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.181s	user 0.115s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1058,"lbm_read_time_us":13814,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32160,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:38.344226 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:38.403360 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.059s	user 0.041s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25854,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.403852 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:38.414295 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.414866 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushMRSOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:38.446985 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushMRSOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1543,"drs_written":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1575,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":2816}
I20260812 06:17:38.447671 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling LogGCOp(1b50a3417c8748fdb7869356dcce1022): free 120100582 bytes of WAL
I20260812 06:17:38.447958 28901 log_reader.cc:385] T 1b50a3417c8748fdb7869356dcce1022: removed 12 log segments from log reader
I20260812 06:17:38.448007 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000027 (ops 132-136)
I20260812 06:17:38.448036 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000028 (ops 137-140)
I20260812 06:17:38.448096 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000029 (ops 141-145)
I20260812 06:17:38.448137 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000030 (ops 146-150)
I20260812 06:17:38.448179 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000031 (ops 151-155)
I20260812 06:17:38.448212 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000032 (ops 156-160)
I20260812 06:17:38.448248 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000033 (ops 161-164)
I20260812 06:17:38.448285 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000034 (ops 165-169)
I20260812 06:17:38.448323 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000035 (ops 170-174)
I20260812 06:17:38.448357 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000036 (ops 175-178)
I20260812 06:17:38.448395 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000037 (ops 179-183)
I20260812 06:17:38.448434 28901 log.cc:1079] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: Deleting log segment in path: /tmp/dist-test-taskFvXLmz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448226140-28595-0/minicluster-data/ts-0-root/wals/1b50a3417c8748fdb7869356dcce1022/wal-000000038 (ops 184-188)
I20260812 06:17:38.474615 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: LogGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:38.475133 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022): 462 bytes on disk
I20260812 06:17:38.475656 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: UndoDeltaBlockGCOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.476398 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=3.181125
I20260812 06:17:38.488514 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4579,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:38.488922 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=2.188937
I20260812 06:17:38.498567 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.499011 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022): perf score=1.000000
I20260812 06:17:38.667348 28595 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.837s	user 1.788s	sys 0.182s
I20260812 06:17:38.713163 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: MajorDeltaCompactionOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.214s	user 0.153s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16986,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37423,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3500}
I20260812 06:17:38.713647 28969 maintenance_manager.cc:419] P bb87c74fdbbb498eb16a0d14c0f27ab0: Scheduling FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022): perf score=14.095187
I20260812 06:17:38.748634 28595 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.003s	sys 0.000s
I20260812 06:17:38.749164 28595 tablet_server.cc:179] TabletServer@127.27.236.193:0 shutting down...
I20260812 06:17:38.761809 28901 maintenance_manager.cc:643] P bb87c74fdbbb498eb16a0d14c0f27ab0: FlushDeltaMemStoresOp(1b50a3417c8748fdb7869356dcce1022) complete. Timing: real 0.048s	user 0.014s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21264,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.762357 28595 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:38.762583 28595 tablet_replica.cc:333] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0: stopping tablet replica
I20260812 06:17:38.762727 28595 raft_consensus.cc:2243] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:38.762916 28595 raft_consensus.cc:2272] T 1b50a3417c8748fdb7869356dcce1022 P bb87c74fdbbb498eb16a0d14c0f27ab0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:38.766120 28595 tablet_server.cc:196] TabletServer@127.27.236.193:0 shutdown complete.
I20260812 06:17:38.783450 28595 master.cc:562] Master@127.27.236.254:41881 shutting down...
I20260812 06:17:38.786949 28595 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:38.787106 28595 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:38.787170 28595 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6da70f01c5b841fbbe0108f08e0c3202: stopping tablet replica
I20260812 06:17:38.799389 28595 master.cc:584] Master@127.27.236.254:41881 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5290 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10650 ms total)

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