[==========] 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:16:40.244561 13439 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.31.254:43443
I20260812 06:16:40.245566 13439 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:16:40.246124 13439 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:40.252722 13439 server_base.cc:1061] running on GCE node
W20260812 06:16:40.252861 13448 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:16:40.252763 13456 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:16:40.253149 13450 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:16:40.253693 13439 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.253787 13439 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:16:40.253813 13439 hybrid_clock.cc:648] HybridClock initialized: now 1786515400253811 us; error 0 us; skew 500 ppm
I20260812 06:16:40.255632 13439 webserver.cc:533] Webserver started at http://127.13.31.254:37857/ using document root <none> and password file <none>
I20260812 06:16:40.256204 13439 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.256258 13439 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.256448 13439 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.258047 13439 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/master-0-root/instance:
uuid: "55173af6cb084ffe98a61fb5164c19bf"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-mjjr"
I20260812 06:16:40.261549 13439 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:40.263614 13466 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:16:40.264681 13439 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.264806 13439 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/master-0-root
uuid: "55173af6cb084ffe98a61fb5164c19bf"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-mjjr"
I20260812 06:16:40.264907 13439 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-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:16:40.281519 13439 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.282135 13439 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:16:40.282316 13439 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.290285 13439 rpc_server.cc:307] RPC server started. Bound to: 127.13.31.254:43443
I20260812 06:16:40.290292 13558 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.31.254:43443 every 8 connection(s)
I20260812 06:16:40.292557 13559 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:16:40.297911 13559 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: Bootstrap starting.
I20260812 06:16:40.300338 13559 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.301237 13559 log.cc:826] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:40.302845 13559 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: No bootstrap required, opened a new log
I20260812 06:16:40.305559 13559 raft_consensus.cc:359] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER }
I20260812 06:16:40.305714 13559 raft_consensus.cc:385] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.305832 13559 raft_consensus.cc:740] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 55173af6cb084ffe98a61fb5164c19bf, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.306409 13559 consensus_queue.cc:260] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [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: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER }
I20260812 06:16:40.306559 13559 raft_consensus.cc:399] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.306658 13559 raft_consensus.cc:493] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.306813 13559 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.307554 13559 raft_consensus.cc:515] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER }
I20260812 06:16:40.308001 13559 leader_election.cc:304] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [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: 55173af6cb084ffe98a61fb5164c19bf; no voters: 
I20260812 06:16:40.308331 13559 leader_election.cc:290] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.308476 13567 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.308740 13567 raft_consensus.cc:697] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 1 LEADER]: Becoming Leader. State: Replica: 55173af6cb084ffe98a61fb5164c19bf, State: Running, Role: LEADER
I20260812 06:16:40.309188 13567 consensus_queue.cc:237] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [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: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER }
I20260812 06:16:40.309329 13559 sys_catalog.cc:565] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:40.311163 13572 sys_catalog.cc:455] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [sys.catalog]: SysCatalogTable state changed. Reason: New leader 55173af6cb084ffe98a61fb5164c19bf. Latest consensus state: current_term: 1 leader_uuid: "55173af6cb084ffe98a61fb5164c19bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER } }
I20260812 06:16:40.311206 13568 sys_catalog.cc:455] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "55173af6cb084ffe98a61fb5164c19bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55173af6cb084ffe98a61fb5164c19bf" member_type: VOTER } }
I20260812 06:16:40.311287 13572 sys_catalog.cc:458] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.311303 13568 sys_catalog.cc:458] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:40.311767 13439 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:16:40.313697 13599 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:16:40.313755 13599 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:16:40.313838 13595 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:40.314553 13595 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:40.319376 13595 catalog_manager.cc:1383] Generated new cluster ID: 32724f2d29af4a97a98a03acf0a290c2
I20260812 06:16:40.319454 13595 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:40.331737 13595 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:40.332548 13595 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:40.337368 13595 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: Generated new TSK 0
I20260812 06:16:40.337944 13595 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:40.344355 13439 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:40.346920 13608 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:16:40.346997 13606 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:16:40.347128 13439 server_base.cc:1061] running on GCE node
W20260812 06:16:40.346933 13605 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:16:40.347450 13439 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:40.347532 13439 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:16:40.347558 13439 hybrid_clock.cc:648] HybridClock initialized: now 1786515400347556 us; error 0 us; skew 500 ppm
I20260812 06:16:40.348531 13439 webserver.cc:533] Webserver started at http://127.13.31.193:45565/ using document root <none> and password file <none>
I20260812 06:16:40.348703 13439 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:40.348773 13439 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:40.348850 13439 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:40.349225 13439 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/instance:
uuid: "1a5fd3a883f845c48cdd99f2ea25bda4"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-mjjr"
I20260812 06:16:40.350740 13439 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:40.351783 13614 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:16:40.352027 13439 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:40.352101 13439 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root
uuid: "1a5fd3a883f845c48cdd99f2ea25bda4"
format_stamp: "Formatted at 2026-08-12 06:16:40 on dist-test-slave-mjjr"
I20260812 06:16:40.352187 13439 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-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:16:40.364440 13439 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:40.364871 13439 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:40.365352 13439 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:40.366197 13439 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:40.366250 13439 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.366315 13439 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:40.366354 13439 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:40.372969 13439 rpc_server.cc:307] RPC server started. Bound to: 127.13.31.193:46345
I20260812 06:16:40.373011 13725 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.31.193:46345 every 8 connection(s)
I20260812 06:16:40.382853 13726 heartbeater.cc:344] Connected to a master server at 127.13.31.254:43443
I20260812 06:16:40.383101 13726 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:40.383606 13726 heartbeater.cc:507] Master 127.13.31.254:43443 requested a full tablet report, sending...
I20260812 06:16:40.385484 13492 ts_manager.cc:194] Registered new tserver with Master: 1a5fd3a883f845c48cdd99f2ea25bda4 (127.13.31.193:46345)
I20260812 06:16:40.385883 13439 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012292062s
I20260812 06:16:40.387017 13492 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48164
I20260812 06:16:40.399132 13492 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48170:
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:16:40.413278 13667 tablet_service.cc:1511] Processing CreateTablet for tablet 186353a3586940428b4ee775ad94349c (DEFAULT_TABLE table=heavy-update-compaction-test [id=ef5bf22d7de249aface09f07ae3db033]), partition=
I20260812 06:16:40.413805 13667 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 186353a3586940428b4ee775ad94349c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:40.416086 13753 tablet_bootstrap.cc:492] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Bootstrap starting.
I20260812 06:16:40.417223 13753 tablet_bootstrap.cc:654] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:40.418354 13753 tablet_bootstrap.cc:492] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: No bootstrap required, opened a new log
I20260812 06:16:40.418462 13753 ts_tablet_manager.cc:1403] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:40.418936 13753 raft_consensus.cc:359] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a5fd3a883f845c48cdd99f2ea25bda4" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 46345 } }
I20260812 06:16:40.419034 13753 raft_consensus.cc:385] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:40.419057 13753 raft_consensus.cc:740] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1a5fd3a883f845c48cdd99f2ea25bda4, State: Initialized, Role: FOLLOWER
I20260812 06:16:40.419252 13753 consensus_queue.cc:260] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [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: "1a5fd3a883f845c48cdd99f2ea25bda4" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 46345 } }
I20260812 06:16:40.419337 13753 raft_consensus.cc:399] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:40.419399 13753 raft_consensus.cc:493] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:40.419456 13753 raft_consensus.cc:3060] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:40.420354 13753 raft_consensus.cc:515] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a5fd3a883f845c48cdd99f2ea25bda4" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 46345 } }
I20260812 06:16:40.420502 13753 leader_election.cc:304] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [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: 1a5fd3a883f845c48cdd99f2ea25bda4; no voters: 
I20260812 06:16:40.420684 13753 leader_election.cc:290] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:40.420971 13759 raft_consensus.cc:2804] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:40.421042 13753 ts_tablet_manager.cc:1434] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:40.421496 13726 heartbeater.cc:499] Master 127.13.31.254:43443 was elected leader, sending a full tablet report...
I20260812 06:16:40.421514 13759 raft_consensus.cc:697] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 1 LEADER]: Becoming Leader. State: Replica: 1a5fd3a883f845c48cdd99f2ea25bda4, State: Running, Role: LEADER
I20260812 06:16:40.421947 13759 consensus_queue.cc:237] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [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: "1a5fd3a883f845c48cdd99f2ea25bda4" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 46345 } }
I20260812 06:16:40.424928 13492 catalog_manager.cc:5719] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1a5fd3a883f845c48cdd99f2ea25bda4 (127.13.31.193). New cstate: current_term: 1 leader_uuid: "1a5fd3a883f845c48cdd99f2ea25bda4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a5fd3a883f845c48cdd99f2ea25bda4" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 46345 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:40.494237 13439 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.019s	sys 0.008s
I20260812 06:16:40.624027 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushMRSOp(186353a3586940428b4ee775ad94349c): perf score=15.086190
I20260812 06:16:40.805249 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushMRSOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.181s	user 0.154s	sys 0.024s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":347,"delete_count":0,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":895,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44593,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":120,"threads_started":1,"update_count":1500}
I20260812 06:16:40.806536 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling LogGCOp(186353a3586940428b4ee775ad94349c): free 20743880 bytes of WAL
I20260812 06:16:40.806910 13622 log_reader.cc:385] T 186353a3586940428b4ee775ad94349c: removed 2 log segments from log reader
I20260812 06:16:40.806984 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000001 (ops 1-6)
I20260812 06:16:40.807050 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000002 (ops 7-11)
I20260812 06:16:40.812552 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: LogGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:40.812889 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=3.181125
I20260812 06:16:40.837134 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.024s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5874,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.837628 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:40.847551 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3953,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.848073 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.018361 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.170s	user 0.111s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":837,"lbm_read_time_us":12659,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26959,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":325,"threads_started":5,"update_count":2500}
I20260812 06:16:41.018957 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.067997 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.049s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17383,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.068473 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c): 16411394 bytes on disk
I20260812 06:16:41.068979 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c) 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:16:41.069420 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:41.080951 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.081439 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.208139 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.127s	user 0.099s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":9204,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22230,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:16:41.208774 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.248099 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.039s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16904,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.248649 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.362030 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.113s	user 0.085s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":322,"lbm_read_time_us":5877,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20266,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.362672 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.398015 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15740,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.398445 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.531983 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.133s	user 0.094s	sys 0.039s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1016,"lbm_read_time_us":8932,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22273,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":66304,"update_count":1500}
I20260812 06:16:41.532670 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.570830 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.038s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16857,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.571349 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:41.582585 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.583243 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.710111 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":667,"lbm_read_time_us":8737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22894,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2000}
I20260812 06:16:41.710683 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.750785 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.040s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.751288 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:41.762974 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.763432 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:41.893796 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.130s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":917,"lbm_read_time_us":9657,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23936,"lbm_writes_lt_1ms":443,"mutex_wait_us":244,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:41.894495 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:41.945324 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.051s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16584,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.945997 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:41.957209 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.957698 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:42.102245 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.144s	user 0.093s	sys 0.050s 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":828,"lbm_read_time_us":10373,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24187,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.103047 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:42.149425 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.046s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16178,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.150053 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushMRSOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:42.205792 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushMRSOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.056s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1843,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:42.206679 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling LogGCOp(186353a3586940428b4ee775ad94349c): free 121006431 bytes of WAL
I20260812 06:16:42.206959 13622 log_reader.cc:385] T 186353a3586940428b4ee775ad94349c: removed 12 log segments from log reader
I20260812 06:16:42.207021 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000003 (ops 12-16)
I20260812 06:16:42.207059 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000004 (ops 17-21)
I20260812 06:16:42.207093 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000005 (ops 22-26)
I20260812 06:16:42.207119 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000006 (ops 27-30)
I20260812 06:16:42.207155 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000007 (ops 31-35)
I20260812 06:16:42.207181 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000008 (ops 36-40)
I20260812 06:16:42.207208 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000009 (ops 41-45)
I20260812 06:16:42.207237 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000010 (ops 46-50)
I20260812 06:16:42.207259 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000011 (ops 51-55)
I20260812 06:16:42.207293 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000012 (ops 56-60)
I20260812 06:16:42.207319 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000013 (ops 61-65)
I20260812 06:16:42.207340 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000014 (ops 66-70)
I20260812 06:16:42.237486 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: LogGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:42.237926 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c): 482 bytes on disk
I20260812 06:16:42.238405 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.238915 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=6.157687
I20260812 06:16:42.275575 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.036s	user 0.023s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":11618,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:42.276136 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:42.286824 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.287297 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:42.489910 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.202s	user 0.109s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1408,"lbm_read_time_us":15500,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32994,"lbm_writes_lt_1ms":643,"mutex_wait_us":567,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":93,"threads_started":1,"update_count":3000}
I20260812 06:16:42.490411 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=14.095187
I20260812 06:16:42.550649 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.060s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.551205 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:42.562294 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4364,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.562793 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:42.750192 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.187s	user 0.143s	sys 0.044s 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":408,"lbm_read_time_us":12060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32278,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:42.750880 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:42.786528 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15084,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.787441 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:42.807078 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.807566 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:42.941803 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.134s	user 0.098s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":9184,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24837,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:16:42.942440 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:42.980088 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.038s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16994,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:42.980535 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:42.991423 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.992007 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.117790 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.126s	user 0.096s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":9092,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25415,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.118422 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:43.159482 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.041s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.160125 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:43.171386 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.172041 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.297057 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.125s	user 0.102s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":180,"lbm_read_time_us":8498,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23636,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:43.297794 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:43.344266 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.344877 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:43.355839 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.356277 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.509641 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.153s	user 0.105s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":643,"lbm_read_time_us":10177,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25656,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.510208 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:43.552042 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.041s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16202,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.552601 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:43.568701 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.569209 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.697019 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":140,"lbm_read_time_us":7989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26175,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:16:43.697799 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:43.733711 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.036s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16117,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.734685 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:43.760577 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.026s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.761103 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:43.771433 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.771919 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushMRSOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.804293 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushMRSOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2201,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:43.805228 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling LogGCOp(186353a3586940428b4ee775ad94349c): free 136275199 bytes of WAL
I20260812 06:16:43.805529 13622 log_reader.cc:385] T 186353a3586940428b4ee775ad94349c: removed 13 log segments from log reader
I20260812 06:16:43.805583 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000015 (ops 71-75)
I20260812 06:16:43.805631 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000016 (ops 76-80)
I20260812 06:16:43.805673 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000017 (ops 81-85)
I20260812 06:16:43.805711 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000018 (ops 86-90)
I20260812 06:16:43.805751 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000019 (ops 91-95)
I20260812 06:16:43.805785 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000020 (ops 96-100)
I20260812 06:16:43.805827 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000021 (ops 101-105)
I20260812 06:16:43.805867 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000022 (ops 106-110)
I20260812 06:16:43.805903 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000023 (ops 111-115)
I20260812 06:16:43.805938 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000024 (ops 116-120)
I20260812 06:16:43.805972 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000025 (ops 121-125)
I20260812 06:16:43.806010 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000026 (ops 126-130)
I20260812 06:16:43.806058 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000027 (ops 131-134)
I20260812 06:16:43.835942 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: LogGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:43.836436 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=5.165500
I20260812 06:16:43.852547 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":6358990,"delete_count":0,"lbm_write_time_us":6682,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:43.853142 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c): 493 bytes on disk
I20260812 06:16:43.853659 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.854161 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:43.870343 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.016s	user 0.004s	sys 0.004s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":3384,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:16:43.870885 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:44.058177 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.187s	user 0.130s	sys 0.048s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979813,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":537,"lbm_read_time_us":12881,"lbm_reads_lt_1ms":767,"lbm_write_time_us":36950,"lbm_writes_lt_1ms":743,"mutex_wait_us":53,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:16:44.059301 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=18.063937
I20260812 06:16:44.123389 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.064s	user 0.028s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":24400,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:44.123994 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:44.135722 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.136257 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:44.359366 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.223s	user 0.156s	sys 0.066s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":17869,"lbm_reads_lt_1ms":672,"lbm_write_time_us":42119,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:16:44.360042 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=14.095187
I20260812 06:16:44.419879 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.060s	user 0.037s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.420513 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:44.432735 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.434804 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:44.613942 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.179s	user 0.109s	sys 0.063s 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":244,"lbm_read_time_us":12657,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31933,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:16:44.614507 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=14.095187
I20260812 06:16:44.675977 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.061s	user 0.042s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21922,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.676517 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:44.687420 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.687920 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:44.870452 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.182s	user 0.117s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":942,"lbm_read_time_us":12183,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32302,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:16:44.871212 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=11.118625
I20260812 06:16:44.903951 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.033s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13500,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:44.904557 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:44.929757 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5553,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.930245 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:44.941116 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.941838 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:45.124887 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.183s	user 0.104s	sys 0.074s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":134,"lbm_read_time_us":11699,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30269,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:16:45.125509 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=11.118625
I20260812 06:16:45.162256 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.037s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16564,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:45.163280 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:45.182960 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.183431 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:45.193105 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3583,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.193562 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushMRSOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:45.224364 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushMRSOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":334,"dirs.run_wall_time_us":1377,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1727,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:45.225097 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling LogGCOp(186353a3586940428b4ee775ad94349c): free 121006700 bytes of WAL
I20260812 06:16:45.225332 13622 log_reader.cc:385] T 186353a3586940428b4ee775ad94349c: removed 12 log segments from log reader
I20260812 06:16:45.225376 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000028 (ops 135-139)
I20260812 06:16:45.225406 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000029 (ops 140-144)
I20260812 06:16:45.225466 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000030 (ops 145-149)
I20260812 06:16:45.225509 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000031 (ops 150-154)
I20260812 06:16:45.225553 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000032 (ops 155-159)
I20260812 06:16:45.225589 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000033 (ops 160-164)
I20260812 06:16:45.225629 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000034 (ops 165-169)
I20260812 06:16:45.225667 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000035 (ops 170-174)
I20260812 06:16:45.225703 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000036 (ops 175-178)
I20260812 06:16:45.225741 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000037 (ops 179-183)
I20260812 06:16:45.225781 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000038 (ops 184-188)
I20260812 06:16:45.225821 13622 log.cc:1079] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/186353a3586940428b4ee775ad94349c/wal-000000039 (ops 189-193)
I20260812 06:16:45.252791 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: LogGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:45.253199 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c): 447 bytes on disk
I20260812 06:16:45.253656 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: UndoDeltaBlockGCOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.254163 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=3.181125
I20260812 06:16:45.276255 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.022s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4604,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.276726 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=2.188937
I20260812 06:16:45.286134 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3537,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.286567 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c): perf score=1.000000
I20260812 06:16:45.415814 13439 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.921s	user 1.820s	sys 0.167s
I20260812 06:16:45.501402 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: MajorDeltaCompactionOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.215s	user 0.129s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15453,"lbm_reads_lt_1ms":771,"lbm_write_time_us":39482,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3500}
I20260812 06:16:45.501883 13728 maintenance_manager.cc:419] P 1a5fd3a883f845c48cdd99f2ea25bda4: Scheduling FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c): perf score=10.126437
I20260812 06:16:45.522193 13439 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.106s	user 0.001s	sys 0.000s
I20260812 06:16:45.522869 13439 tablet_server.cc:179] TabletServer@127.13.31.193:0 shutting down...
I20260812 06:16:45.547887 13622 maintenance_manager.cc:643] P 1a5fd3a883f845c48cdd99f2ea25bda4: FlushDeltaMemStoresOp(186353a3586940428b4ee775ad94349c) complete. Timing: real 0.046s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15549,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:45.548632 13439 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.549398 13439 tablet_replica.cc:333] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4: stopping tablet replica
I20260812 06:16:45.549619 13439 raft_consensus.cc:2243] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.549830 13439 raft_consensus.cc:2272] T 186353a3586940428b4ee775ad94349c P 1a5fd3a883f845c48cdd99f2ea25bda4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.564990 13439 tablet_server.cc:196] TabletServer@127.13.31.193:0 shutdown complete.
I20260812 06:16:45.569658 13439 master.cc:562] Master@127.13.31.254:43443 shutting down...
I20260812 06:16:45.573895 13439 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.574095 13439 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.574194 13439 tablet_replica.cc:333] T 00000000000000000000000000000000 P 55173af6cb084ffe98a61fb5164c19bf: stopping tablet replica
I20260812 06:16:45.586652 13439 master.cc:584] Master@127.13.31.254:43443 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5430 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:45.674577 13439 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.31.254:43925
I20260812 06:16:45.674937 13439 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:45.677361 13439 server_base.cc:1061] running on GCE node
W20260812 06:16:45.677426 13788 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:16:45.677443 13786 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:16:45.677443 13784 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:16:45.677820 13439 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.677865 13439 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:16:45.677888 13439 hybrid_clock.cc:648] HybridClock initialized: now 1786515405677888 us; error 0 us; skew 500 ppm
I20260812 06:16:45.678680 13439 webserver.cc:533] Webserver started at http://127.13.31.254:38479/ using document root <none> and password file <none>
I20260812 06:16:45.678813 13439 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.678853 13439 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.678984 13439 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.679338 13439 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/master-0-root/instance:
uuid: "c95b0d8a3ff14e32bd758677563f4444"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-mjjr"
I20260812 06:16:45.680912 13439 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:45.681756 13800 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:16:45.682026 13439 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.682094 13439 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/master-0-root
uuid: "c95b0d8a3ff14e32bd758677563f4444"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-mjjr"
I20260812 06:16:45.682188 13439 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-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:16:45.702332 13439 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.702793 13439 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.707356 13439 rpc_server.cc:307] RPC server started. Bound to: 127.13.31.254:43925
I20260812 06:16:45.709965 13899 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.31.254:43925 every 8 connection(s)
I20260812 06:16:45.710551 13901 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:16:45.717715 13901 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444: Bootstrap starting.
I20260812 06:16:45.718542 13901 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.719583 13901 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444: No bootstrap required, opened a new log
I20260812 06:16:45.720044 13901 raft_consensus.cc:359] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER }
I20260812 06:16:45.720131 13901 raft_consensus.cc:385] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.720178 13901 raft_consensus.cc:740] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c95b0d8a3ff14e32bd758677563f4444, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.720366 13901 consensus_queue.cc:260] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [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: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER }
I20260812 06:16:45.720436 13901 raft_consensus.cc:399] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.720506 13901 raft_consensus.cc:493] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.720570 13901 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.721289 13901 raft_consensus.cc:515] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER }
I20260812 06:16:45.721436 13901 leader_election.cc:304] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [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: c95b0d8a3ff14e32bd758677563f4444; no voters: 
I20260812 06:16:45.721665 13901 leader_election.cc:290] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.721880 13912 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.722102 13912 raft_consensus.cc:697] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 1 LEADER]: Becoming Leader. State: Replica: c95b0d8a3ff14e32bd758677563f4444, State: Running, Role: LEADER
I20260812 06:16:45.722132 13901 sys_catalog.cc:565] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:45.722258 13912 consensus_queue.cc:237] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [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: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER }
I20260812 06:16:45.722719 13916 sys_catalog.cc:455] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c95b0d8a3ff14e32bd758677563f4444. Latest consensus state: current_term: 1 leader_uuid: "c95b0d8a3ff14e32bd758677563f4444" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER } }
I20260812 06:16:45.722831 13916 sys_catalog.cc:458] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.722698 13914 sys_catalog.cc:455] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c95b0d8a3ff14e32bd758677563f4444" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c95b0d8a3ff14e32bd758677563f4444" member_type: VOTER } }
I20260812 06:16:45.722949 13914 sys_catalog.cc:458] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.723171 13924 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:45.724071 13924 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:45.724344 13439 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:45.725920 13924 catalog_manager.cc:1383] Generated new cluster ID: aa74f91b5ed3428e9533588bbeab5894
I20260812 06:16:45.725980 13924 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:45.752439 13924 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:45.753063 13924 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:45.757776 13924 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444: Generated new TSK 0
I20260812 06:16:45.758002 13924 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:45.788920 13439 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:45.791009 13941 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:16:45.791193 13947 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:16:45.791203 13945 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:16:45.791246 13439 server_base.cc:1061] running on GCE node
I20260812 06:16:45.791484 13439 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.791525 13439 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:16:45.791540 13439 hybrid_clock.cc:648] HybridClock initialized: now 1786515405791541 us; error 0 us; skew 500 ppm
I20260812 06:16:45.792495 13439 webserver.cc:533] Webserver started at http://127.13.31.193:41575/ using document root <none> and password file <none>
I20260812 06:16:45.792683 13439 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.792750 13439 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.792831 13439 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.793251 13439 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/instance:
uuid: "fac03ae306504dc485dfcbcc9c2670b8"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-mjjr"
I20260812 06:16:45.794761 13439 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:45.795764 13958 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:16:45.796018 13439 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.796083 13439 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root
uuid: "fac03ae306504dc485dfcbcc9c2670b8"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-mjjr"
I20260812 06:16:45.796175 13439 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-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:16:45.804373 13439 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.804670 13439 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.804919 13439 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:45.805395 13439 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:45.805433 13439 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.805496 13439 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:45.805541 13439 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.810376 13439 rpc_server.cc:307] RPC server started. Bound to: 127.13.31.193:38861
I20260812 06:16:45.811486 14085 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.31.193:38861 every 8 connection(s)
I20260812 06:16:45.822579 14087 heartbeater.cc:344] Connected to a master server at 127.13.31.254:43925
I20260812 06:16:45.822685 14087 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:45.822918 14087 heartbeater.cc:507] Master 127.13.31.254:43925 requested a full tablet report, sending...
I20260812 06:16:45.823541 13826 ts_manager.cc:194] Registered new tserver with Master: fac03ae306504dc485dfcbcc9c2670b8 (127.13.31.193:38861)
I20260812 06:16:45.823598 13439 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012223066s
I20260812 06:16:45.824473 13826 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43990
I20260812 06:16:45.830446 13826 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44002:
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:16:45.839089 14001 tablet_service.cc:1511] Processing CreateTablet for tablet e20d96eacbfc4b778728a8ce5eb0c3cd (DEFAULT_TABLE table=heavy-update-compaction-test [id=04183e7d334a433fb7120d7197c16806]), partition=
I20260812 06:16:45.839375 14001 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e20d96eacbfc4b778728a8ce5eb0c3cd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:45.841465 14104 tablet_bootstrap.cc:492] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Bootstrap starting.
I20260812 06:16:45.842304 14104 tablet_bootstrap.cc:654] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.843382 14104 tablet_bootstrap.cc:492] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: No bootstrap required, opened a new log
I20260812 06:16:45.843492 14104 ts_tablet_manager.cc:1403] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:45.843953 14104 raft_consensus.cc:359] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fac03ae306504dc485dfcbcc9c2670b8" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 38861 } }
I20260812 06:16:45.844070 14104 raft_consensus.cc:385] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.844121 14104 raft_consensus.cc:740] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fac03ae306504dc485dfcbcc9c2670b8, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.844300 14104 consensus_queue.cc:260] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [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: "fac03ae306504dc485dfcbcc9c2670b8" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 38861 } }
I20260812 06:16:45.844406 14104 raft_consensus.cc:399] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.844444 14104 raft_consensus.cc:493] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.844503 14104 raft_consensus.cc:3060] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.845412 14104 raft_consensus.cc:515] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fac03ae306504dc485dfcbcc9c2670b8" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 38861 } }
I20260812 06:16:45.845563 14104 leader_election.cc:304] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [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: fac03ae306504dc485dfcbcc9c2670b8; no voters: 
I20260812 06:16:45.845783 14104 leader_election.cc:290] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.845961 14107 raft_consensus.cc:2804] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.846103 14087 heartbeater.cc:499] Master 127.13.31.254:43925 was elected leader, sending a full tablet report...
I20260812 06:16:45.846134 14104 ts_tablet_manager.cc:1434] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:45.846200 14107 raft_consensus.cc:697] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 1 LEADER]: Becoming Leader. State: Replica: fac03ae306504dc485dfcbcc9c2670b8, State: Running, Role: LEADER
I20260812 06:16:45.846354 14107 consensus_queue.cc:237] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [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: "fac03ae306504dc485dfcbcc9c2670b8" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 38861 } }
I20260812 06:16:45.847697 13826 catalog_manager.cc:5719] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 reported cstate change: term changed from 0 to 1, leader changed from <none> to fac03ae306504dc485dfcbcc9c2670b8 (127.13.31.193). New cstate: current_term: 1 leader_uuid: "fac03ae306504dc485dfcbcc9c2670b8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fac03ae306504dc485dfcbcc9c2670b8" member_type: VOTER last_known_addr { host: "127.13.31.193" port: 38861 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:45.909845 13439 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.012s
I20260812 06:16:46.061995 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=19.054940
I20260812 06:16:46.220939 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.159s	user 0.120s	sys 0.037s Metrics: {"bytes_written":12717735,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":814,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40949,"lbm_writes_lt_1ms":767,"mutex_wait_us":883,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":4480,"update_count":1550}
I20260812 06:16:46.221601 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): free 20743880 bytes of WAL
I20260812 06:16:46.221810 13963 log_reader.cc:385] T e20d96eacbfc4b778728a8ce5eb0c3cd: removed 2 log segments from log reader
I20260812 06:16:46.221869 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000001 (ops 1-6)
I20260812 06:16:46.221911 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000002 (ops 7-11)
I20260812 06:16:46.226814 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:46.227129 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:46.243533 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.244091 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): 16411395 bytes on disk
I20260812 06:16:46.244529 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.245018 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:46.254601 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3672,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.255229 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:46.415756 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.160s	user 0.105s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":812,"lbm_read_time_us":11287,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29230,"lbm_writes_lt_1ms":543,"mutex_wait_us":119,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":362,"threads_started":5,"update_count":2500}
I20260812 06:16:46.416401 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:46.469379 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.053s	user 0.028s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21273,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.469802 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:46.479866 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.480463 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:46.655809 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.175s	user 0.125s	sys 0.034s 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":373,"lbm_read_time_us":10318,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32620,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:46.656358 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:46.704061 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.047s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20414,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.704576 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:46.847936 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.143s	user 0.110s	sys 0.033s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1203,"lbm_read_time_us":10044,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22797,"lbm_writes_lt_1ms":443,"mutex_wait_us":394,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.848560 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:46.899154 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.050s	user 0.018s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22987,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":35712,"update_count":2000}
I20260812 06:16:46.899710 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:46.910698 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.911164 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:47.087781 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.176s	user 0.116s	sys 0.054s 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":264,"lbm_read_time_us":11785,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26672,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65024,"update_count":2500}
I20260812 06:16:47.088447 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:47.144393 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.056s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19483,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.144933 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:47.156780 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.157275 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:47.320624 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.163s	user 0.120s	sys 0.041s 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":198,"lbm_read_time_us":10949,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32452,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:47.321381 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=11.118625
I20260812 06:16:47.351500 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.030s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12967,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:47.352384 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:47.379132 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5458,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.379575 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:47.390064 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s 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:16:47.390493 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:47.421720 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1772,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:47.422348 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): free 112239307 bytes of WAL
I20260812 06:16:47.422576 13963 log_reader.cc:385] T e20d96eacbfc4b778728a8ce5eb0c3cd: removed 11 log segments from log reader
I20260812 06:16:47.422621 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000003 (ops 12-16)
I20260812 06:16:47.422649 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000004 (ops 17-21)
I20260812 06:16:47.422710 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000005 (ops 22-26)
I20260812 06:16:47.422766 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000006 (ops 27-30)
I20260812 06:16:47.422804 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000007 (ops 31-35)
I20260812 06:16:47.422863 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000008 (ops 36-40)
I20260812 06:16:47.422909 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000009 (ops 41-45)
I20260812 06:16:47.422945 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000010 (ops 46-50)
I20260812 06:16:47.422986 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000011 (ops 51-55)
I20260812 06:16:47.423017 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000012 (ops 56-60)
I20260812 06:16:47.423058 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000013 (ops 61-65)
I20260812 06:16:47.447342 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:47.447822 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=3.181125
I20260812 06:16:47.469096 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.021s	user 0.005s	sys 0.014s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4504,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.469589 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): free 12017932 bytes of WAL
I20260812 06:16:47.469856 13963 log_reader.cc:385] T e20d96eacbfc4b778728a8ce5eb0c3cd: removed 1 log segments from log reader
I20260812 06:16:47.469901 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000014 (ops 66-70)
I20260812 06:16:47.472295 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:47.472651 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): 462 bytes on disk
I20260812 06:16:47.473061 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.473487 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:47.483302 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.483929 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:47.730917 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.247s	user 0.164s	sys 0.082s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":725,"lbm_read_time_us":17362,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37897,"lbm_writes_lt_1ms":743,"mutex_wait_us":53,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:16:47.731725 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=18.063937
I20260812 06:16:47.804118 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.072s	user 0.057s	sys 0.000s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25967,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:47.804592 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:47.814991 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.815451 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:48.016835 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.201s	user 0.126s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":12789,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32759,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:48.017613 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=15.087375
I20260812 06:16:48.067818 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.050s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21932,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:48.068571 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.082561 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.083007 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:48.264608 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.181s	user 0.149s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":44,"lbm_read_time_us":10925,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32534,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:48.265196 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:48.322885 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.056s	user 0.016s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19731,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.323580 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.341734 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.342322 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:48.530212 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.188s	user 0.123s	sys 0.061s 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":212,"lbm_read_time_us":13596,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29576,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:16:48.530966 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:48.589905 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.059s	user 0.016s	sys 0.038s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19986,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.590612 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.602001 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.602491 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:48.793740 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.191s	user 0.100s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":12444,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29379,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:16:48.794466 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:48.856353 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.062s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25977,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.856865 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.877682 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.878340 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:48.913192 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1733,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2230,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:48.913841 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): free 112239316 bytes of WAL
I20260812 06:16:48.914069 13963 log_reader.cc:385] T e20d96eacbfc4b778728a8ce5eb0c3cd: removed 11 log segments from log reader
I20260812 06:16:48.914116 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000015 (ops 71-75)
I20260812 06:16:48.914168 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000016 (ops 76-80)
I20260812 06:16:48.914216 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000017 (ops 81-85)
I20260812 06:16:48.914268 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000018 (ops 86-90)
I20260812 06:16:48.914315 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000019 (ops 91-95)
I20260812 06:16:48.914377 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000020 (ops 96-100)
I20260812 06:16:48.914422 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000021 (ops 101-105)
I20260812 06:16:48.914461 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000022 (ops 106-110)
I20260812 06:16:48.914500 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000023 (ops 111-115)
I20260812 06:16:48.914541 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000024 (ops 116-120)
I20260812 06:16:48.914579 13963 log.cc:1079] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: Deleting log segment in path: /tmp/dist-test-taskDhAP6S/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515400233706-13439-0/minicluster-data/ts-0-root/wals/e20d96eacbfc4b778728a8ce5eb0c3cd/wal-000000025 (ops 121-124)
I20260812 06:16:48.937577 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: LogGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:48.938030 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd): 448 bytes on disk
I20260812 06:16:48.938683 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: UndoDeltaBlockGCOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":107,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.939283 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.958702 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.019s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5350,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.959154 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:48.969275 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.969664 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:49.208348 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.239s	user 0.142s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":342,"lbm_read_time_us":15133,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39349,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:16:49.209113 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=18.063937
I20260812 06:16:49.282557 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.073s	user 0.049s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28746,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:49.283032 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:49.295018 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.295663 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:49.500124 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.204s	user 0.140s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":719,"lbm_read_time_us":14144,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33615,"lbm_writes_lt_1ms":643,"mutex_wait_us":265,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:16:49.500715 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:49.567023 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.066s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26993,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.567513 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:49.582819 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5703,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.583477 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:49.764071 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.180s	user 0.124s	sys 0.053s 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":1035,"lbm_read_time_us":13094,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29455,"lbm_writes_lt_1ms":543,"mutex_wait_us":354,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:16:49.764599 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=14.095187
I20260812 06:16:49.822252 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.058s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22827,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.822769 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:49.837589 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.838418 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:50.083307 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: MajorDeltaCompactionOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.245s	user 0.168s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":70,"lbm_read_time_us":15998,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41912,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:16:50.084131 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=18.063937
I20260812 06:16:50.183960 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.099s	user 0.024s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25106,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:50.184516 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=6.157687
I20260812 06:16:50.271524 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.087s	user 0.022s	sys 0.005s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":12216,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:50.272153 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=3.181125
I20260812 06:16:50.374363 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.102s	user 0.013s	sys 0.000s Metrics: {"bytes_written":5169287,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":129,"reinsert_count":0,"update_count":630}
I20260812 06:16:50.374970 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=9.134250
I20260812 06:16:50.478996 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.104s	user 0.010s	sys 0.020s Metrics: {"bytes_written":11240862,"delete_count":0,"lbm_write_time_us":13460,"lbm_writes_lt_1ms":277,"reinsert_count":0,"update_count":1370}
I20260812 06:16:50.479818 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=7.149875
I20260812 06:16:50.581689 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.102s	user 0.017s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11710,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:50.582276 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=10.126437
I20260812 06:16:50.681056 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.099s	user 0.022s	sys 0.011s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":14377,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:50.681833 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=6.157687
I20260812 06:16:50.781497 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.099s	user 0.025s	sys 0.000s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":11124,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:50.782349 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=6.157687
I20260812 06:16:50.812615 13439 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.903s	user 1.829s	sys 0.157s
I20260812 06:16:50.883338 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.101s	user 0.022s	sys 0.007s Metrics: {"bytes_written":8328152,"delete_count":0,"lbm_write_time_us":12774,"lbm_writes_lt_1ms":206,"mutex_wait_us":220,"reinsert_count":0,"update_count":1015}
I20260812 06:16:50.884233 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=2.188937
I20260812 06:16:50.987609 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushDeltaMemStoresOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.103s	user 0.010s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":7221,"lbm_writes_lt_1ms":100,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":485}
I20260812 06:16:50.988484 14088 maintenance_manager.cc:419] P fac03ae306504dc485dfcbcc9c2670b8: Scheduling FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd): perf score=1.000000
I20260812 06:16:51.034749 13439 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.222s	user 0.001s	sys 0.000s
I20260812 06:16:51.035279 13439 tablet_server.cc:179] TabletServer@127.13.31.193:0 shutting down...
I20260812 06:16:51.091810 13963 maintenance_manager.cc:643] P fac03ae306504dc485dfcbcc9c2670b8: FlushMRSOp(e20d96eacbfc4b778728a8ce5eb0c3cd) complete. Timing: real 0.103s	user 0.026s	sys 0.007s Metrics: {"bytes_written":1603405,"cfile_init":1,"dirs.queue_time_us":266,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":73706,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2128,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":39,"thread_start_us":115,"threads_started":1}
I20260812 06:16:51.092639 13439 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:51.092871 13439 tablet_replica.cc:333] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8: stopping tablet replica
I20260812 06:16:51.093036 13439 raft_consensus.cc:2243] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:51.093243 13439 raft_consensus.cc:2272] T e20d96eacbfc4b778728a8ce5eb0c3cd P fac03ae306504dc485dfcbcc9c2670b8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:51.096979 13439 tablet_server.cc:196] TabletServer@127.13.31.193:0 shutdown complete.
I20260812 06:16:51.099181 13439 master.cc:562] Master@127.13.31.254:43925 shutting down...
I20260812 06:16:51.102525 13439 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:51.102660 13439 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:51.102707 13439 tablet_replica.cc:333] T 00000000000000000000000000000000 P c95b0d8a3ff14e32bd758677563f4444: stopping tablet replica
I20260812 06:16:51.115166 13439 master.cc:584] Master@127.13.31.254:43925 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5554 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10985 ms total)

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