[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:23.970049 22895 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.91.254:33283
I20260812 06:17:23.971092 22895 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:23.971696 22895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.978474 22903 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:23.978529 22900 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:23.978634 22895 server_base.cc:1061] running on GCE node
W20260812 06:17:23.978868 22901 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:23.979439 22895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.979560 22895 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:23.979628 22895 hybrid_clock.cc:648] HybridClock initialized: now 1786515443979625 us; error 0 us; skew 500 ppm
I20260812 06:17:23.981592 22895 webserver.cc:533] Webserver started at http://127.22.91.254:42217/ using document root <none> and password file <none>
I20260812 06:17:23.982178 22895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.982275 22895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.982566 22895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.984412 22895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/master-0-root/instance:
uuid: "a0225bcd22c14b8db34057ecf6e75de2"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-mvvj"
I20260812 06:17:23.988035 22895 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:23.990260 22909 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:23.991277 22895 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:23.991423 22895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/master-0-root
uuid: "a0225bcd22c14b8db34057ecf6e75de2"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-mvvj"
I20260812 06:17:23.991528 22895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.004083 22895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.004739 22895 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:24.004931 22895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.012920 22895 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.254:33283
I20260812 06:17:24.012917 22962 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.254:33283 every 8 connection(s)
I20260812 06:17:24.015237 22963 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.020828 22963 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: Bootstrap starting.
I20260812 06:17:24.023223 22963 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.024228 22963 log.cc:826] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:24.026098 22963 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: No bootstrap required, opened a new log
I20260812 06:17:24.028968 22963 raft_consensus.cc:359] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER }
I20260812 06:17:24.029143 22963 raft_consensus.cc:385] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.029222 22963 raft_consensus.cc:740] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a0225bcd22c14b8db34057ecf6e75de2, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.029848 22963 consensus_queue.cc:260] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [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: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER }
I20260812 06:17:24.030018 22963 raft_consensus.cc:399] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.030098 22963 raft_consensus.cc:493] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.030283 22963 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.031107 22963 raft_consensus.cc:515] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER }
I20260812 06:17:24.031567 22963 leader_election.cc:304] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [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: a0225bcd22c14b8db34057ecf6e75de2; no voters: 
I20260812 06:17:24.031950 22963 leader_election.cc:290] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.032100 22967 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.032371 22967 raft_consensus.cc:697] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 1 LEADER]: Becoming Leader. State: Replica: a0225bcd22c14b8db34057ecf6e75de2, State: Running, Role: LEADER
I20260812 06:17:24.032789 22967 consensus_queue.cc:237] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [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: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER }
I20260812 06:17:24.032999 22963 sys_catalog.cc:565] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:24.034727 22969 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a0225bcd22c14b8db34057ecf6e75de2. Latest consensus state: current_term: 1 leader_uuid: "a0225bcd22c14b8db34057ecf6e75de2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER } }
I20260812 06:17:24.034780 22968 sys_catalog.cc:455] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a0225bcd22c14b8db34057ecf6e75de2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0225bcd22c14b8db34057ecf6e75de2" member_type: VOTER } }
I20260812 06:17:24.034917 22968 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.034855 22969 sys_catalog.cc:458] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:24.035377 22981 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:24.035444 22895 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:24.037837 22981 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:24.042440 22981 catalog_manager.cc:1383] Generated new cluster ID: 9caaedc9dad04844971ed47758a64fa5
I20260812 06:17:24.042510 22981 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:24.060132 22981 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:24.061347 22981 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:24.074618 22981 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: Generated new TSK 0
I20260812 06:17:24.075488 22981 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:24.100726 22895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:24.103590 22989 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.103732 22992 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:24.103946 22990 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:24.103999 22895 server_base.cc:1061] running on GCE node
I20260812 06:17:24.104245 22895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:24.104310 22895 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:24.104336 22895 hybrid_clock.cc:648] HybridClock initialized: now 1786515444104335 us; error 0 us; skew 500 ppm
I20260812 06:17:24.105353 22895 webserver.cc:533] Webserver started at http://127.22.91.193:36389/ using document root <none> and password file <none>
I20260812 06:17:24.105549 22895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:24.105626 22895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:24.105710 22895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:24.106114 22895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/instance:
uuid: "f26c300487624c3b9d13938e6dbee1e9"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-mvvj"
I20260812 06:17:24.107730 22895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:24.108825 22997 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.109078 22895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:24.109153 22895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root
uuid: "f26c300487624c3b9d13938e6dbee1e9"
format_stamp: "Formatted at 2026-08-12 06:17:24 on dist-test-slave-mvvj"
I20260812 06:17:24.109244 22895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:24.119369 22895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:24.119920 22895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:24.120502 22895 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:24.121408 22895 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:24.121464 22895 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.121539 22895 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:24.121577 22895 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:24.128522 22895 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.193:32999
I20260812 06:17:24.128556 23065 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.193:32999 every 8 connection(s)
I20260812 06:17:24.139411 23066 heartbeater.cc:344] Connected to a master server at 127.22.91.254:33283
I20260812 06:17:24.139694 23066 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:24.140178 23066 heartbeater.cc:507] Master 127.22.91.254:33283 requested a full tablet report, sending...
I20260812 06:17:24.141587 22926 ts_manager.cc:194] Registered new tserver with Master: f26c300487624c3b9d13938e6dbee1e9 (127.22.91.193:32999)
I20260812 06:17:24.141705 22895 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012480219s
I20260812 06:17:24.142901 22926 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56006
I20260812 06:17:24.151723 22926 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56012:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:24.166087 23028 tablet_service.cc:1511] Processing CreateTablet for tablet a6aa397e101848f78307e7a63967873e (DEFAULT_TABLE table=heavy-update-compaction-test [id=cfbdcb89644a4a18a4bedd081f0bb832]), partition=
I20260812 06:17:24.166585 23028 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a6aa397e101848f78307e7a63967873e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.169633 23079 tablet_bootstrap.cc:492] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Bootstrap starting.
I20260812 06:17:24.170747 23079 tablet_bootstrap.cc:654] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.172063 23079 tablet_bootstrap.cc:492] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: No bootstrap required, opened a new log
I20260812 06:17:24.172179 23079 ts_tablet_manager.cc:1403] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:24.172986 23079 raft_consensus.cc:359] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c300487624c3b9d13938e6dbee1e9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 32999 } }
I20260812 06:17:24.173111 23079 raft_consensus.cc:385] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.173148 23079 raft_consensus.cc:740] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f26c300487624c3b9d13938e6dbee1e9, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.173329 23079 consensus_queue.cc:260] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [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: "f26c300487624c3b9d13938e6dbee1e9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 32999 } }
I20260812 06:17:24.173425 23079 raft_consensus.cc:399] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.173461 23079 raft_consensus.cc:493] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.173524 23079 raft_consensus.cc:3060] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.174561 23079 raft_consensus.cc:515] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c300487624c3b9d13938e6dbee1e9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 32999 } }
I20260812 06:17:24.174719 23079 leader_election.cc:304] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [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: f26c300487624c3b9d13938e6dbee1e9; no voters: 
I20260812 06:17:24.174942 23079 leader_election.cc:290] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.175122 23081 raft_consensus.cc:2804] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.175369 23079 ts_tablet_manager.cc:1434] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:24.175527 23081 raft_consensus.cc:697] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 1 LEADER]: Becoming Leader. State: Replica: f26c300487624c3b9d13938e6dbee1e9, State: Running, Role: LEADER
I20260812 06:17:24.175736 23081 consensus_queue.cc:237] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [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: "f26c300487624c3b9d13938e6dbee1e9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 32999 } }
I20260812 06:17:24.175792 23066 heartbeater.cc:499] Master 127.22.91.254:33283 was elected leader, sending a full tablet report...
I20260812 06:17:24.178860 22926 catalog_manager.cc:5719] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 reported cstate change: term changed from 0 to 1, leader changed from <none> to f26c300487624c3b9d13938e6dbee1e9 (127.22.91.193). New cstate: current_term: 1 leader_uuid: "f26c300487624c3b9d13938e6dbee1e9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f26c300487624c3b9d13938e6dbee1e9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 32999 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:24.244302 22895 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.014s	sys 0.012s
I20260812 06:17:24.379748 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushMRSOp(a6aa397e101848f78307e7a63967873e): perf score=19.054940
I20260812 06:17:24.563246 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushMRSOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.183s	user 0.146s	sys 0.033s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":223,"delete_count":0,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":924,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46385,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":2944,"thread_start_us":152,"threads_started":1,"update_count":1500}
I20260812 06:17:24.564385 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling LogGCOp(a6aa397e101848f78307e7a63967873e): free 20743880 bytes of WAL
I20260812 06:17:24.564699 23003 log_reader.cc:385] T a6aa397e101848f78307e7a63967873e: removed 2 log segments from log reader
I20260812 06:17:24.564778 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000001 (ops 1-6)
I20260812 06:17:24.564849 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000002 (ops 7-11)
I20260812 06:17:24.569029 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: LogGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:24.569416 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:24.588585 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.589084 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:24.725642 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.136s	user 0.105s	sys 0.028s 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":448,"lbm_read_time_us":6981,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22570,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":337,"threads_started":5,"update_count":2000}
I20260812 06:17:24.726259 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e): 16411392 bytes on disk
I20260812 06:17:24.726846 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.727340 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:24.765185 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.038s	user 0.032s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16161,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.765707 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:24.782065 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.782814 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:24.920923 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.138s	user 0.126s	sys 0.011s 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":1260,"lbm_read_time_us":8718,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27953,"lbm_writes_lt_1ms":443,"mutex_wait_us":366,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.921406 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:24.965934 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.044s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.966454 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:24.977142 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.977806 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.093978 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.116s	user 0.098s	sys 0.018s 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":249,"lbm_read_time_us":7586,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22194,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:25.094700 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:25.146292 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.051s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.146955 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:25.157565 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.158035 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.307134 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.149s	user 0.098s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":595,"lbm_read_time_us":11001,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24303,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:17:25.307610 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:25.358886 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.051s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16959,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.359380 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:25.370544 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.371170 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.498798 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.127s	user 0.094s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":9416,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24257,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2000}
I20260812 06:17:25.499281 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:25.546124 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.047s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.546761 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:25.558359 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.559082 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.680020 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.121s	user 0.095s	sys 0.024s 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":557,"lbm_read_time_us":9500,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22331,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:17:25.680684 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:25.727372 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.046s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17097,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.728044 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:25.738940 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.739413 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushMRSOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.774473 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushMRSOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.035s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1563,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1497,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:25.775357 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:25.940244 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.165s	user 0.112s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1173,"lbm_read_time_us":11133,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26372,"lbm_writes_lt_1ms":443,"mutex_wait_us":354,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:17:25.942770 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling LogGCOp(a6aa397e101848f78307e7a63967873e): free 115943176 bytes of WAL
I20260812 06:17:25.943109 23003 log_reader.cc:385] T a6aa397e101848f78307e7a63967873e: removed 11 log segments from log reader
I20260812 06:17:25.943177 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000003 (ops 12-16)
I20260812 06:17:25.943235 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000004 (ops 17-21)
I20260812 06:17:25.943274 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000005 (ops 22-26)
I20260812 06:17:25.943303 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000006 (ops 27-31)
I20260812 06:17:25.943343 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000007 (ops 32-36)
I20260812 06:17:25.943382 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000008 (ops 37-41)
I20260812 06:17:25.943414 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000009 (ops 42-46)
I20260812 06:17:25.943454 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000010 (ops 47-51)
I20260812 06:17:25.943487 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000011 (ops 52-56)
I20260812 06:17:25.943526 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000012 (ops 57-61)
I20260812 06:17:25.943564 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000013 (ops 62-66)
I20260812 06:17:25.968618 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: LogGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.026s	user 0.001s	sys 0.024s Metrics: {}
I20260812 06:17:25.969138 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:26.023597 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.054s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.024083 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e): 447 bytes on disk
I20260812 06:17:26.024507 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e) 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:17:26.024959 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:26.035974 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.036583 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:26.216286 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.180s	user 0.105s	sys 0.059s 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":1014,"lbm_read_time_us":11136,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30492,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:26.216837 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:26.268718 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.052s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.269243 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:26.285588 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.286155 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:26.435081 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.149s	user 0.115s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":9919,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29341,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.435753 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:26.471954 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16269,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.472501 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:26.485952 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.486464 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:26.631219 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.145s	user 0.089s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4669,"dirs.run_cpu_time_us":1291,"dirs.run_wall_time_us":6969,"lbm_read_time_us":10284,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23929,"lbm_writes_lt_1ms":443,"mutex_wait_us":3916,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:26.631821 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:26.666735 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.035s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14242,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.667303 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:26.679116 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.012s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.679890 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:26.803965 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.124s	user 0.094s	sys 0.029s 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":859,"lbm_read_time_us":8212,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24207,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:17:26.804723 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:26.857600 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.053s	user 0.012s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15621,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.858269 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:26.869203 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.869696 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:27.020066 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.150s	user 0.106s	sys 0.040s 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":322,"lbm_read_time_us":10582,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24671,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:27.020648 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:27.067279 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.046s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14998,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.067771 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:27.084378 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.085212 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:27.213505 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.128s	user 0.104s	sys 0.024s 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":214,"lbm_read_time_us":9922,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23950,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:27.214123 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:27.258603 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.044s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15780,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.259236 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:27.270686 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.271270 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushMRSOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:27.299698 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushMRSOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1282,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1688,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:27.300513 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling LogGCOp(a6aa397e101848f78307e7a63967873e): free 124710298 bytes of WAL
I20260812 06:17:27.300738 23003 log_reader.cc:385] T a6aa397e101848f78307e7a63967873e: removed 12 log segments from log reader
I20260812 06:17:27.300782 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000014 (ops 67-71)
I20260812 06:17:27.300812 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000015 (ops 72-76)
I20260812 06:17:27.300872 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000016 (ops 77-81)
I20260812 06:17:27.300912 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000017 (ops 82-86)
I20260812 06:17:27.300947 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000018 (ops 87-91)
I20260812 06:17:27.300997 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000019 (ops 92-96)
I20260812 06:17:27.301023 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000020 (ops 97-101)
I20260812 06:17:27.301060 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000021 (ops 102-106)
I20260812 06:17:27.301097 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000022 (ops 107-111)
I20260812 06:17:27.301136 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000023 (ops 112-116)
I20260812 06:17:27.301172 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000024 (ops 117-121)
I20260812 06:17:27.301210 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000025 (ops 122-126)
I20260812 06:17:27.328320 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: LogGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:27.328770 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e): 471 bytes on disk
I20260812 06:17:27.329267 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.329871 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=3.181125
I20260812 06:17:27.342206 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4991,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:27.342725 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:27.352350 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3562,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.352887 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:27.527107 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.174s	user 0.123s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2479,"lbm_read_time_us":11095,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35197,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:17:27.527805 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:27.576655 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.049s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.577239 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:27.589129 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.589660 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:27.754837 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.165s	user 0.100s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":9982,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30978,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:27.755560 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:27.814419 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.059s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27755,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.815116 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:27.830274 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.830789 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.029836 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.199s	user 0.136s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":629,"lbm_read_time_us":12876,"lbm_reads_lt_1ms":564,"lbm_write_time_us":36149,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55936,"update_count":2500}
I20260812 06:17:28.030505 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:28.068984 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.038s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16824,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.069684 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.222401 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.152s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":610,"lbm_read_time_us":11032,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23329,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.222954 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:28.256986 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.034s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14755,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.257522 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:28.273109 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.273586 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.402990 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.129s	user 0.126s	sys 0.003s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":8728,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26658,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:28.403672 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:28.445536 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.042s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15154,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.445986 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:28.457019 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.457803 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.587857 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.130s	user 0.108s	sys 0.021s 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":276,"lbm_read_time_us":9362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24700,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:28.588713 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:28.634589 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.046s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16629,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.635067 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:28.645925 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.646616 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushMRSOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.677035 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushMRSOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1385,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1963,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:28.677834 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling LogGCOp(a6aa397e101848f78307e7a63967873e): free 112692600 bytes of WAL
I20260812 06:17:28.678088 23003 log_reader.cc:385] T a6aa397e101848f78307e7a63967873e: removed 11 log segments from log reader
I20260812 06:17:28.678159 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000026 (ops 127-131)
I20260812 06:17:28.678215 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000027 (ops 132-136)
I20260812 06:17:28.678282 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000028 (ops 137-141)
I20260812 06:17:28.678329 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000029 (ops 142-146)
I20260812 06:17:28.678365 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000030 (ops 147-151)
I20260812 06:17:28.678399 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000031 (ops 152-156)
I20260812 06:17:28.678435 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000032 (ops 157-161)
I20260812 06:17:28.678472 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000033 (ops 162-166)
I20260812 06:17:28.678517 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000034 (ops 167-171)
I20260812 06:17:28.678555 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000035 (ops 172-176)
I20260812 06:17:28.678592 23003 log.cc:1079] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/a6aa397e101848f78307e7a63967873e/wal-000000036 (ops 177-181)
I20260812 06:17:28.702786 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: LogGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:28.703274 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=3.181125
I20260812 06:17:28.719564 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5278,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:28.720189 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:28.734309 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5224,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.734951 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e): 448 bytes on disk
I20260812 06:17:28.735515 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: UndoDeltaBlockGCOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.736128 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:28.926141 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.190s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":728,"lbm_read_time_us":13241,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36413,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:28.926913 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=14.095187
I20260812 06:17:28.988552 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.061s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23154,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.989087 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=2.188937
I20260812 06:17:29.001044 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.001715 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:29.124318 22895 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.880s	user 1.858s	sys 0.143s
I20260812 06:17:29.148376 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.146s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11897,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28789,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:29.149034 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e): perf score=10.126437
I20260812 06:17:29.174459 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: FlushDeltaMemStoresOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.025s	user 0.016s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11879,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.174973 23067 maintenance_manager.cc:419] P f26c300487624c3b9d13938e6dbee1e9: Scheduling MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e): perf score=1.000000
I20260812 06:17:29.201279 22895 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.076s	user 0.004s	sys 0.000s
I20260812 06:17:29.202097 22895 tablet_server.cc:179] TabletServer@127.22.91.193:0 shutting down...
I20260812 06:17:29.282459 23003 maintenance_manager.cc:643] P f26c300487624c3b9d13938e6dbee1e9: MajorDeltaCompactionOp(a6aa397e101848f78307e7a63967873e) complete. Timing: real 0.107s	user 0.076s	sys 0.030s 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":652,"lbm_read_time_us":8318,"lbm_reads_lt_1ms":367,"lbm_write_time_us":22327,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":23168,"update_count":1500}
I20260812 06:17:29.283547 22895 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:29.284032 22895 tablet_replica.cc:333] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9: stopping tablet replica
I20260812 06:17:29.284300 22895 raft_consensus.cc:2243] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.284590 22895 raft_consensus.cc:2272] T a6aa397e101848f78307e7a63967873e P f26c300487624c3b9d13938e6dbee1e9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.300555 22895 tablet_server.cc:196] TabletServer@127.22.91.193:0 shutdown complete.
I20260812 06:17:29.315981 22895 master.cc:562] Master@127.22.91.254:33283 shutting down...
I20260812 06:17:29.320009 22895 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.320221 22895 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.320308 22895 tablet_replica.cc:333] T 00000000000000000000000000000000 P a0225bcd22c14b8db34057ecf6e75de2: stopping tablet replica
I20260812 06:17:29.332827 22895 master.cc:584] Master@127.22.91.254:33283 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5452 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:29.422577 22895 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.91.254:40323
I20260812 06:17:29.423000 22895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.425580 23102 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:29.425578 23100 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:29.425751 23104 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:29.425926 22895 server_base.cc:1061] running on GCE node
I20260812 06:17:29.426086 22895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.426124 22895 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:29.426141 22895 hybrid_clock.cc:648] HybridClock initialized: now 1786515449426140 us; error 0 us; skew 500 ppm
I20260812 06:17:29.426995 22895 webserver.cc:533] Webserver started at http://127.22.91.254:35615/ using document root <none> and password file <none>
I20260812 06:17:29.427135 22895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.427179 22895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.427232 22895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.427634 22895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/master-0-root/instance:
uuid: "3cc70862ae1847a79c9efe335cabe109"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-mvvj"
I20260812 06:17:29.429270 22895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:29.430264 23109 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.430657 22895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.430752 22895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/master-0-root
uuid: "3cc70862ae1847a79c9efe335cabe109"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-mvvj"
I20260812 06:17:29.430845 22895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:29.439152 22895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.439610 22895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.444186 22895 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.254:40323
I20260812 06:17:29.446630 23172 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.254:40323 every 8 connection(s)
I20260812 06:17:29.447386 23173 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:29.461616 23173 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109: Bootstrap starting.
I20260812 06:17:29.462654 23173 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.463806 23173 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109: No bootstrap required, opened a new log
I20260812 06:17:29.464306 23173 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER }
I20260812 06:17:29.464406 23173 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.464428 23173 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3cc70862ae1847a79c9efe335cabe109, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.464603 23173 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [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: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER }
I20260812 06:17:29.464676 23173 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.464740 23173 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.464799 23173 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.465642 23173 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER }
I20260812 06:17:29.465792 23173 leader_election.cc:304] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [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: 3cc70862ae1847a79c9efe335cabe109; no voters: 
I20260812 06:17:29.466017 23173 leader_election.cc:290] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.466161 23176 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.466372 23176 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 1 LEADER]: Becoming Leader. State: Replica: 3cc70862ae1847a79c9efe335cabe109, State: Running, Role: LEADER
I20260812 06:17:29.466511 23173 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:29.466524 23176 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [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: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER }
I20260812 06:17:29.467067 23177 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3cc70862ae1847a79c9efe335cabe109" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER } }
I20260812 06:17:29.467156 23177 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.467113 23178 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3cc70862ae1847a79c9efe335cabe109. Latest consensus state: current_term: 1 leader_uuid: "3cc70862ae1847a79c9efe335cabe109" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cc70862ae1847a79c9efe335cabe109" member_type: VOTER } }
I20260812 06:17:29.467198 23178 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.467391 23181 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:29.468299 23181 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:29.468680 22895 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:29.470085 23181 catalog_manager.cc:1383] Generated new cluster ID: 9fffba36492c4d1db534e74f01982f08
I20260812 06:17:29.470142 23181 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:29.491184 23181 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:29.491760 23181 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:29.497701 23181 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109: Generated new TSK 0
I20260812 06:17:29.497895 23181 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:29.501012 22895 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.503243 23198 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:29.503263 22895 server_base.cc:1061] running on GCE node
W20260812 06:17:29.503250 23195 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:29.503250 23196 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:29.503674 22895 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.503741 22895 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:29.503767 22895 hybrid_clock.cc:648] HybridClock initialized: now 1786515449503766 us; error 0 us; skew 500 ppm
I20260812 06:17:29.504750 22895 webserver.cc:533] Webserver started at http://127.22.91.193:37435/ using document root <none> and password file <none>
I20260812 06:17:29.504933 22895 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.505023 22895 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.505106 22895 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.505512 22895 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/instance:
uuid: "72e6155a699d4deab1a2519f48c224c9"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-mvvj"
I20260812 06:17:29.507081 22895 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.508224 23203 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.508505 22895 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.508598 22895 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root
uuid: "72e6155a699d4deab1a2519f48c224c9"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-mvvj"
I20260812 06:17:29.508689 22895 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:29.531261 22895 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.531750 22895 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.532183 22895 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:29.532666 22895 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:29.532727 22895 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.532788 22895 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:29.532840 22895 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.537155 22895 rpc_server.cc:307] RPC server started. Bound to: 127.22.91.193:46539
I20260812 06:17:29.537191 23274 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.91.193:46539 every 8 connection(s)
I20260812 06:17:29.546856 23276 heartbeater.cc:344] Connected to a master server at 127.22.91.254:40323
I20260812 06:17:29.547030 23276 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:29.547334 23276 heartbeater.cc:507] Master 127.22.91.254:40323 requested a full tablet report, sending...
I20260812 06:17:29.548058 23129 ts_manager.cc:194] Registered new tserver with Master: 72e6155a699d4deab1a2519f48c224c9 (127.22.91.193:46539)
I20260812 06:17:29.548662 22895 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011074024s
I20260812 06:17:29.548863 23129 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51288
I20260812 06:17:29.556034 23129 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51298:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:29.565577 23234 tablet_service.cc:1511] Processing CreateTablet for tablet 8aba07b72bb74deda0d85d2d768ae64d (DEFAULT_TABLE table=heavy-update-compaction-test [id=69fb72d491d44ef3abdd764a43ab623e]), partition=
I20260812 06:17:29.565922 23234 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8aba07b72bb74deda0d85d2d768ae64d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:29.568114 23290 tablet_bootstrap.cc:492] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Bootstrap starting.
I20260812 06:17:29.569074 23290 tablet_bootstrap.cc:654] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.570356 23290 tablet_bootstrap.cc:492] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: No bootstrap required, opened a new log
I20260812 06:17:29.570495 23290 ts_tablet_manager.cc:1403] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:29.571023 23290 raft_consensus.cc:359] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72e6155a699d4deab1a2519f48c224c9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 46539 } }
I20260812 06:17:29.571144 23290 raft_consensus.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.571193 23290 raft_consensus.cc:740] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 72e6155a699d4deab1a2519f48c224c9, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.571367 23290 consensus_queue.cc:260] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [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: "72e6155a699d4deab1a2519f48c224c9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 46539 } }
I20260812 06:17:29.571511 23290 raft_consensus.cc:399] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.571579 23290 raft_consensus.cc:493] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.571648 23290 raft_consensus.cc:3060] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.572508 23290 raft_consensus.cc:515] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72e6155a699d4deab1a2519f48c224c9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 46539 } }
I20260812 06:17:29.572675 23290 leader_election.cc:304] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [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: 72e6155a699d4deab1a2519f48c224c9; no voters: 
I20260812 06:17:29.572927 23290 leader_election.cc:290] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.573071 23292 raft_consensus.cc:2804] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.573275 23290 ts_tablet_manager.cc:1434] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:29.573309 23292 raft_consensus.cc:697] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 1 LEADER]: Becoming Leader. State: Replica: 72e6155a699d4deab1a2519f48c224c9, State: Running, Role: LEADER
I20260812 06:17:29.573354 23276 heartbeater.cc:499] Master 127.22.91.254:40323 was elected leader, sending a full tablet report...
I20260812 06:17:29.573513 23292 consensus_queue.cc:237] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [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: "72e6155a699d4deab1a2519f48c224c9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 46539 } }
I20260812 06:17:29.574954 23128 catalog_manager.cc:5719] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 72e6155a699d4deab1a2519f48c224c9 (127.22.91.193). New cstate: current_term: 1 leader_uuid: "72e6155a699d4deab1a2519f48c224c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72e6155a699d4deab1a2519f48c224c9" member_type: VOTER last_known_addr { host: "127.22.91.193" port: 46539 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:29.635465 22895 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.011s	sys 0.012s
I20260812 06:17:29.788172 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=19.054940
I20260812 06:17:29.938810 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.150s	user 0.115s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1037,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37211,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:29.939452 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 20743831 bytes of WAL
I20260812 06:17:29.939689 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 2 log segments from log reader
I20260812 06:17:29.939733 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000001 (ops 1-6)
I20260812 06:17:29.939764 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000002 (ops 7-11)
I20260812 06:17:29.944638 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:29.945235 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d): 16411395 bytes on disk
I20260812 06:17:29.945806 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.946408 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:29.970455 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5040,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:17:29.971040 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:29.981680 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.982198 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:30.151086 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.169s	user 0.130s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1470,"lbm_read_time_us":11275,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29185,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":383,"threads_started":5,"update_count":2500}
I20260812 06:17:30.151790 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:30.200882 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.049s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20324,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.201347 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:30.213989 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.214491 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:30.363575 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.149s	user 0.124s	sys 0.024s 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":202,"lbm_read_time_us":11615,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29889,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:30.364670 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:30.397271 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14323,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:30.397845 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:30.414180 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.414690 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:30.541185 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.126s	user 0.106s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":7386,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25612,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:17:30.543112 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:30.589573 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.046s	user 0.019s	sys 0.026s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14649,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.590211 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:30.601780 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.602254 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:30.751703 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.149s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":887,"lbm_read_time_us":11309,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22348,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.752581 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:30.799160 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.046s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.799649 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:30.811031 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.811758 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:30.932047 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.120s	user 0.091s	sys 0.029s 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":234,"lbm_read_time_us":9273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22360,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:30.932801 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:30.972568 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.040s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.973045 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:30.984225 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.984884 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:31.106155 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.121s	user 0.098s	sys 0.022s 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":508,"lbm_read_time_us":8362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25093,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":50304,"update_count":2000}
I20260812 06:17:31.106768 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:31.153231 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.046s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19615,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:17:31.153728 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:31.164093 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.164714 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:31.196553 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1362,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2064,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:31.197156 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 124710290 bytes of WAL
I20260812 06:17:31.197386 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 12 log segments from log reader
I20260812 06:17:31.197432 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000003 (ops 12-16)
I20260812 06:17:31.197463 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000004 (ops 17-21)
I20260812 06:17:31.197527 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000005 (ops 22-26)
I20260812 06:17:31.197567 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000006 (ops 27-31)
I20260812 06:17:31.197607 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000007 (ops 32-36)
I20260812 06:17:31.197666 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000008 (ops 37-41)
I20260812 06:17:31.197726 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000009 (ops 42-46)
I20260812 06:17:31.197759 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000010 (ops 47-51)
I20260812 06:17:31.197795 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000011 (ops 52-56)
I20260812 06:17:31.197834 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000012 (ops 57-61)
I20260812 06:17:31.197873 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000013 (ops 62-66)
I20260812 06:17:31.197921 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000014 (ops 67-71)
I20260812 06:17:31.225229 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:31.225687 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d): 472 bytes on disk
I20260812 06:17:31.226230 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:17:31.226693 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=3.181125
I20260812 06:17:31.239444 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:31.239964 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:31.249845 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3535,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.250370 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:31.419567 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.169s	user 0.145s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":211,"lbm_read_time_us":13966,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31587,"lbm_writes_lt_1ms":643,"mutex_wait_us":9,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:31.420288 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:31.475344 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.055s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20559,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.475989 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:31.494273 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6950,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.494951 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:31.652993 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.158s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":938,"lbm_read_time_us":9769,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33006,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":241536,"update_count":2500}
I20260812 06:17:31.653662 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:31.690068 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.036s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16156,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.690652 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:31.704679 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5063,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.705341 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:31.854655 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.149s	user 0.091s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":109,"lbm_read_time_us":10615,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22997,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:31.855337 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:31.894942 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.039s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12971,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.895571 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:31.918236 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6091,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.918875 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:32.063876 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.145s	user 0.098s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":83,"lbm_read_time_us":9259,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23476,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:17:32.064615 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:32.101191 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.036s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15483,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:32.101892 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.124070 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.124524 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.134337 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.134821 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:32.283573 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.149s	user 0.112s	sys 0.036s 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":219,"lbm_read_time_us":10719,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28626,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2500}
I20260812 06:17:32.284379 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:32.317682 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.033s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14262,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.318210 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.329489 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.330084 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:32.458076 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.128s	user 0.110s	sys 0.018s 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":442,"lbm_read_time_us":10392,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22214,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:17:32.458647 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=10.126437
I20260812 06:17:32.503070 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.044s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15271,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.503609 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.515305 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.516014 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:32.548539 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1492,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2006,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:32.549173 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 108535504 bytes of WAL
I20260812 06:17:32.549434 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 11 log segments from log reader
I20260812 06:17:32.549496 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000015 (ops 72-76)
I20260812 06:17:32.549546 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000016 (ops 77-81)
I20260812 06:17:32.549585 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000017 (ops 82-86)
I20260812 06:17:32.549652 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000018 (ops 87-91)
I20260812 06:17:32.549693 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000019 (ops 92-96)
I20260812 06:17:32.549736 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000020 (ops 97-100)
I20260812 06:17:32.549774 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000021 (ops 101-105)
I20260812 06:17:32.549813 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000022 (ops 106-110)
I20260812 06:17:32.549852 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000023 (ops 111-114)
I20260812 06:17:32.549886 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000024 (ops 115-119)
I20260812 06:17:32.549923 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000025 (ops 120-124)
I20260812 06:17:32.571602 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.022s	user 0.003s	sys 0.015s Metrics: {}
I20260812 06:17:32.572177 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.597231 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.025s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6580,"lbm_writes_lt_1ms":103,"mutex_wait_us":2,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.597688 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 11564877 bytes of WAL
I20260812 06:17:32.597890 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 1 log segments from log reader
I20260812 06:17:32.597939 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000026 (ops 125-128)
I20260812 06:17:32.600139 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:32.600492 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d): 447 bytes on disk
I20260812 06:17:32.600888 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d) 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:17:32.601359 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.612725 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.613168 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:32.784618 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.171s	user 0.145s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":556,"lbm_read_time_us":11518,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34478,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:32.787483 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:32.846818 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.059s	user 0.039s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.847364 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:32.858453 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.859212 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:33.031602 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.172s	user 0.121s	sys 0.036s 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":379,"lbm_read_time_us":10743,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30821,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51712,"update_count":2500}
I20260812 06:17:33.032855 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:33.101652 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.069s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25323,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.102241 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:33.113569 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.114332 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:33.287019 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.172s	user 0.143s	sys 0.027s 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":420,"lbm_read_time_us":12642,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28670,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:17:33.287811 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:33.334954 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.047s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14687,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:33.335562 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:33.351547 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.016s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4641,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.352072 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:33.362769 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.363233 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:33.542897 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.179s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":476,"lbm_read_time_us":12009,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32893,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:33.543598 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:33.602268 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.059s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23831,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.602900 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:33.614132 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.614620 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:33.824591 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.210s	user 0.157s	sys 0.052s 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":364,"lbm_read_time_us":13724,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34719,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:33.825205 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:33.878317 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.053s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20264,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.878932 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:33.890851 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.891355 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:34.071686 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.180s	user 0.124s	sys 0.056s 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":502,"lbm_read_time_us":13768,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32386,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:34.072603 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=11.118625
I20260812 06:17:34.113525 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.040s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18188,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:34.114233 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:34.125631 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.126153 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:34.158416 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushMRSOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:34.159096 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 117302827 bytes of WAL
I20260812 06:17:34.159324 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 12 log segments from log reader
I20260812 06:17:34.159386 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000027 (ops 129-133)
I20260812 06:17:34.159441 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000028 (ops 134-138)
I20260812 06:17:34.159499 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000029 (ops 139-142)
I20260812 06:17:34.159539 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000030 (ops 143-147)
I20260812 06:17:34.159576 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000031 (ops 148-152)
I20260812 06:17:34.159613 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000032 (ops 153-157)
I20260812 06:17:34.159650 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000033 (ops 158-162)
I20260812 06:17:34.159687 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000034 (ops 163-166)
I20260812 06:17:34.159724 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000035 (ops 167-171)
I20260812 06:17:34.159761 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000036 (ops 172-176)
I20260812 06:17:34.159798 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000037 (ops 177-181)
I20260812 06:17:34.159858 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000038 (ops 182-186)
I20260812 06:17:34.186025 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:34.186487 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=3.181125
I20260812 06:17:34.201561 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.202015 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling LogGCOp(8aba07b72bb74deda0d85d2d768ae64d): free 11564891 bytes of WAL
I20260812 06:17:34.202208 23208 log_reader.cc:385] T 8aba07b72bb74deda0d85d2d768ae64d: removed 1 log segments from log reader
I20260812 06:17:34.202268 23208 log.cc:1079] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: Deleting log segment in path: /tmp/dist-test-taskm6QlP7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443959251-22895-0/minicluster-data/ts-0-root/wals/8aba07b72bb74deda0d85d2d768ae64d/wal-000000039 (ops 187-190)
I20260812 06:17:34.204456 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: LogGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:34.204790 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d): 483 bytes on disk
I20260812 06:17:34.205195 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: UndoDeltaBlockGCOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.205688 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:34.215812 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.217285 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:34.401940 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.184s	user 0.134s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2829,"lbm_read_time_us":12768,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30261,"lbm_writes_lt_1ms":643,"mutex_wait_us":1825,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:17:34.402704 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=14.095187
I20260812 06:17:34.451821 22895 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.816s	user 1.817s	sys 0.134s
I20260812 06:17:34.464941 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.062s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.465591 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=2.188937
I20260812 06:17:34.482667 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: FlushDeltaMemStoresOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":500}
I20260812 06:17:34.483286 23277 maintenance_manager.cc:419] P 72e6155a699d4deab1a2519f48c224c9: Scheduling MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d): perf score=1.000000
I20260812 06:17:34.538128 22895 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.001s	sys 0.000s
I20260812 06:17:34.538763 22895 tablet_server.cc:179] TabletServer@127.22.91.193:0 shutting down...
I20260812 06:17:34.613978 23208 maintenance_manager.cc:643] P 72e6155a699d4deab1a2519f48c224c9: MajorDeltaCompactionOp(8aba07b72bb74deda0d85d2d768ae64d) complete. Timing: real 0.130s	user 0.096s	sys 0.034s Metrics: {"cfile_cache_hit":262,"cfile_cache_hit_bytes":10709239,"cfile_cache_miss":270,"cfile_cache_miss_bytes":14065449,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":272,"lbm_read_time_us":7092,"lbm_reads_lt_1ms":302,"lbm_write_time_us":24970,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":39936,"update_count":2500}
I20260812 06:17:34.614671 22895 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:34.615113 22895 tablet_replica.cc:333] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9: stopping tablet replica
I20260812 06:17:34.615273 22895 raft_consensus.cc:2243] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.615491 22895 raft_consensus.cc:2272] T 8aba07b72bb74deda0d85d2d768ae64d P 72e6155a699d4deab1a2519f48c224c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.619060 22895 tablet_server.cc:196] TabletServer@127.22.91.193:0 shutdown complete.
I20260812 06:17:34.660755 22895 master.cc:562] Master@127.22.91.254:40323 shutting down...
I20260812 06:17:34.664386 22895 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.664623 22895 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.664703 22895 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3cc70862ae1847a79c9efe335cabe109: stopping tablet replica
I20260812 06:17:34.677214 22895 master.cc:584] Master@127.22.91.254:40323 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5342 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10796 ms total)

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