[==========] 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:20:01.412189 12560 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.68.62:42717
I20260812 06:20:01.413417 12560 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:20:01.414158 12560 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:01.422573 12570 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:20:01.422564 12567 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:20:01.422683 12560 server_base.cc:1061] running on GCE node
W20260812 06:20:01.422564 12566 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:20:01.423465 12560 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:01.423580 12560 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:20:01.423658 12560 hybrid_clock.cc:648] HybridClock initialized: now 1786515601423655 us; error 0 us; skew 500 ppm
I20260812 06:20:01.425954 12560 webserver.cc:533] Webserver started at http://127.12.68.62:39561/ using document root <none> and password file <none>
I20260812 06:20:01.426592 12560 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:01.426669 12560 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:01.426940 12560 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:01.428802 12560 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/master-0-root/instance:
uuid: "460969a19e3c4bbdb7c9ef4499496524"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-g350"
I20260812 06:20:01.433116 12560 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.006s	sys 0.000s
I20260812 06:20:01.435953 12575 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:20:01.437353 12560 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:01.437583 12560 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/master-0-root
uuid: "460969a19e3c4bbdb7c9ef4499496524"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-g350"
I20260812 06:20:01.437826 12560 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-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:20:01.465492 12560 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:01.466495 12560 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:20:01.466781 12560 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:01.478083 12560 rpc_server.cc:307] RPC server started. Bound to: 127.12.68.62:42717
I20260812 06:20:01.478133 12642 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.68.62:42717 every 8 connection(s)
I20260812 06:20:01.481319 12644 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:20:01.487501 12644 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: Bootstrap starting.
I20260812 06:20:01.490221 12644 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:01.491350 12644 log.cc:826] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:01.493700 12644 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: No bootstrap required, opened a new log
I20260812 06:20:01.496982 12644 raft_consensus.cc:359] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER }
I20260812 06:20:01.497217 12644 raft_consensus.cc:385] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:01.497262 12644 raft_consensus.cc:740] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 460969a19e3c4bbdb7c9ef4499496524, State: Initialized, Role: FOLLOWER
I20260812 06:20:01.498072 12644 consensus_queue.cc:260] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [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: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER }
I20260812 06:20:01.498250 12644 raft_consensus.cc:399] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:01.498377 12644 raft_consensus.cc:493] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:01.498571 12644 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:01.499603 12644 raft_consensus.cc:515] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER }
I20260812 06:20:01.500207 12644 leader_election.cc:304] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [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: 460969a19e3c4bbdb7c9ef4499496524; no voters: 
I20260812 06:20:01.500612 12644 leader_election.cc:290] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:01.500998 12649 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:01.501463 12649 raft_consensus.cc:697] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 1 LEADER]: Becoming Leader. State: Replica: 460969a19e3c4bbdb7c9ef4499496524, State: Running, Role: LEADER
I20260812 06:20:01.502013 12644 sys_catalog.cc:565] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:01.502219 12649 consensus_queue.cc:237] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [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: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER }
I20260812 06:20:01.505187 12650 sys_catalog.cc:455] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "460969a19e3c4bbdb7c9ef4499496524" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER } }
I20260812 06:20:01.505189 12651 sys_catalog.cc:455] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 460969a19e3c4bbdb7c9ef4499496524. Latest consensus state: current_term: 1 leader_uuid: "460969a19e3c4bbdb7c9ef4499496524" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "460969a19e3c4bbdb7c9ef4499496524" member_type: VOTER } }
I20260812 06:20:01.505410 12650 sys_catalog.cc:458] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.505414 12651 sys_catalog.cc:458] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:01.505218 12560 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:01.507973 12667 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:01.508082 12667 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:01.508193 12668 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:01.509366 12668 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:01.516290 12668 catalog_manager.cc:1383] Generated new cluster ID: ea4bbefb1bb041e5a19821c111376a0a
I20260812 06:20:01.516556 12668 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:01.528579 12668 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:01.530195 12668 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:01.537009 12668 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: Generated new TSK 0
I20260812 06:20:01.537962 12668 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:01.571151 12560 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:01.574788 12675 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:20:01.574896 12673 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:20:01.575119 12672 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:20:01.575290 12560 server_base.cc:1061] running on GCE node
I20260812 06:20:01.575506 12560 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:01.575557 12560 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:20:01.575582 12560 hybrid_clock.cc:648] HybridClock initialized: now 1786515601575580 us; error 0 us; skew 500 ppm
I20260812 06:20:01.576681 12560 webserver.cc:533] Webserver started at http://127.12.68.1:37197/ using document root <none> and password file <none>
I20260812 06:20:01.576880 12560 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:01.576943 12560 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:01.577021 12560 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:01.577484 12560 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/instance:
uuid: "d903ee4346d94392bbc7dae61111442a"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-g350"
I20260812 06:20:01.579547 12560 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:01.580857 12680 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:20:01.581241 12560 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:01.581388 12560 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root
uuid: "d903ee4346d94392bbc7dae61111442a"
format_stamp: "Formatted at 2026-08-12 06:20:01 on dist-test-slave-g350"
I20260812 06:20:01.581497 12560 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-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:20:01.596669 12560 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:01.597332 12560 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:01.598063 12560 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:01.599164 12560 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:01.599261 12560 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:01.599359 12560 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:01.599411 12560 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:01.608501 12560 rpc_server.cc:307] RPC server started. Bound to: 127.12.68.1:37801
I20260812 06:20:01.608534 12759 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.68.1:37801 every 8 connection(s)
I20260812 06:20:01.623733 12761 heartbeater.cc:344] Connected to a master server at 127.12.68.62:42717
I20260812 06:20:01.624215 12761 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:01.624909 12761 heartbeater.cc:507] Master 127.12.68.62:42717 requested a full tablet report, sending...
I20260812 06:20:01.627038 12596 ts_manager.cc:194] Registered new tserver with Master: d903ee4346d94392bbc7dae61111442a (127.12.68.1:37801)
I20260812 06:20:01.627151 12560 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017750724s
I20260812 06:20:01.628718 12596 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40356
I20260812 06:20:01.640287 12596 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40370:
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:20:01.662259 12714 tablet_service.cc:1511] Processing CreateTablet for tablet 6068a27dc0f645d9ba062fb493c20aa8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=89881840294d489ebbb828524aea66dd]), partition=
I20260812 06:20:01.663208 12714 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6068a27dc0f645d9ba062fb493c20aa8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:01.668908 12775 tablet_bootstrap.cc:492] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Bootstrap starting.
I20260812 06:20:01.670325 12775 tablet_bootstrap.cc:654] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:01.672255 12775 tablet_bootstrap.cc:492] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: No bootstrap required, opened a new log
I20260812 06:20:01.672482 12775 ts_tablet_manager.cc:1403] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:20:01.673174 12775 raft_consensus.cc:359] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d903ee4346d94392bbc7dae61111442a" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 37801 } }
I20260812 06:20:01.673334 12775 raft_consensus.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:01.673374 12775 raft_consensus.cc:740] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d903ee4346d94392bbc7dae61111442a, State: Initialized, Role: FOLLOWER
I20260812 06:20:01.673635 12775 consensus_queue.cc:260] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [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: "d903ee4346d94392bbc7dae61111442a" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 37801 } }
I20260812 06:20:01.673775 12775 raft_consensus.cc:399] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:01.673832 12775 raft_consensus.cc:493] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:01.673889 12775 raft_consensus.cc:3060] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:01.674813 12775 raft_consensus.cc:515] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d903ee4346d94392bbc7dae61111442a" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 37801 } }
I20260812 06:20:01.675001 12775 leader_election.cc:304] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [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: d903ee4346d94392bbc7dae61111442a; no voters: 
I20260812 06:20:01.675279 12775 leader_election.cc:290] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:01.675482 12777 raft_consensus.cc:2804] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:01.675725 12775 ts_tablet_manager.cc:1434] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:01.675969 12761 heartbeater.cc:499] Master 127.12.68.62:42717 was elected leader, sending a full tablet report...
I20260812 06:20:01.676007 12777 raft_consensus.cc:697] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 1 LEADER]: Becoming Leader. State: Replica: d903ee4346d94392bbc7dae61111442a, State: Running, Role: LEADER
I20260812 06:20:01.676254 12777 consensus_queue.cc:237] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [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: "d903ee4346d94392bbc7dae61111442a" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 37801 } }
I20260812 06:20:01.680003 12596 catalog_manager.cc:5719] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a reported cstate change: term changed from 0 to 1, leader changed from <none> to d903ee4346d94392bbc7dae61111442a (127.12.68.1). New cstate: current_term: 1 leader_uuid: "d903ee4346d94392bbc7dae61111442a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d903ee4346d94392bbc7dae61111442a" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 37801 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:01.762152 12560 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.072s	user 0.030s	sys 0.003s
I20260812 06:20:01.859999 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.125253
I20260812 06:20:02.022895 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.162s	user 0.118s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":217,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1158,"drs_written":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37728,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":146,"threads_started":1,"update_count":1500}
I20260812 06:20:02.024349 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling LogGCOp(6068a27dc0f645d9ba062fb493c20aa8): free 8725963 bytes of WAL
I20260812 06:20:02.024693 12686 log_reader.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8: removed 1 log segments from log reader
I20260812 06:20:02.024766 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000001 (ops 1-6)
I20260812 06:20:02.027334 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: LogGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:02.027769 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:02.045303 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.045913 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8): 8206539 bytes on disk
I20260812 06:20:02.046765 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.047546 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:02.228416 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.181s	user 0.114s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":840,"lbm_read_time_us":8104,"lbm_reads_lt_1ms":460,"lbm_write_time_us":31970,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":318,"threads_started":5,"update_count":2000}
I20260812 06:20:02.229028 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:02.287403 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.058s	user 0.017s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22420,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:20:02.288092 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:02.301842 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.302383 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:02.433018 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.130s	user 0.101s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1409,"lbm_read_time_us":9244,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24842,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:20:02.433702 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:02.483927 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.050s	user 0.014s	sys 0.029s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16750,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.484474 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:02.495163 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.495668 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:02.649443 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.154s	user 0.092s	sys 0.058s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1216,"lbm_read_time_us":10993,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24573,"lbm_writes_lt_1ms":443,"mutex_wait_us":362,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:20:02.650260 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:02.703744 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.053s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.704414 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:02.718145 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.718801 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:02.864565 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.146s	user 0.109s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1309,"lbm_read_time_us":9958,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29918,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:02.865330 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:02.901317 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.036s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16036,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:02.901889 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:02.914055 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.914809 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:03.049269 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.134s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":818,"lbm_read_time_us":8169,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28152,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:20:03.050377 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:03.097198 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.047s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.097920 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:03.111167 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.111734 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:03.240108 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.128s	user 0.103s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":7639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25445,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.240794 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:03.288992 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.048s	user 0.018s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16214,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:20:03.289567 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:03.300782 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.301271 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:03.349642 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.048s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":318,"dirs.run_wall_time_us":1674,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1464,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:03.350642 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling LogGCOp(6068a27dc0f645d9ba062fb493c20aa8): free 112239308 bytes of WAL
I20260812 06:20:03.350957 12686 log_reader.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8: removed 11 log segments from log reader
I20260812 06:20:03.351022 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000002 (ops 7-11)
I20260812 06:20:03.351063 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000003 (ops 12-16)
I20260812 06:20:03.351085 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000004 (ops 17-21)
I20260812 06:20:03.351112 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000005 (ops 22-26)
I20260812 06:20:03.351140 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000006 (ops 27-31)
I20260812 06:20:03.351172 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000007 (ops 32-36)
I20260812 06:20:03.351203 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000008 (ops 37-40)
I20260812 06:20:03.351226 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000009 (ops 41-45)
I20260812 06:20:03.351248 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000010 (ops 46-50)
I20260812 06:20:03.351274 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000011 (ops 51-55)
I20260812 06:20:03.351308 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000012 (ops 56-60)
I20260812 06:20:03.380834 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: LogGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:03.381402 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:03.399191 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.399865 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:03.572216 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.172s	user 0.107s	sys 0.058s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692877,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2565,"lbm_read_time_us":10385,"lbm_reads_lt_1ms":565,"lbm_write_time_us":28717,"lbm_writes_lt_1ms":543,"mutex_wait_us":899,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":97,"threads_started":1,"update_count":2500}
I20260812 06:20:03.572888 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8): 447 bytes on disk
I20260812 06:20:03.573490 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.574206 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=14.095187
I20260812 06:20:03.633059 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.058s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19710,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.633769 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:03.646978 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.647655 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:03.843201 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.195s	user 0.116s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":13526,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35659,"lbm_writes_lt_1ms":543,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:20:03.843927 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=11.118625
I20260812 06:20:03.890494 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":20443,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:03.891237 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:03.904568 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5117,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.905081 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.071800 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.167s	user 0.110s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590343,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":453,"lbm_read_time_us":12211,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27258,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:20:04.072525 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:04.107338 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15436,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.107944 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:04.120801 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.121488 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.260185 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.138s	user 0.101s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":504,"lbm_read_time_us":9895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26316,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":106112,"update_count":2000}
I20260812 06:20:04.261240 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:04.304980 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.043s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18919,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.305502 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:04.316533 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.317444 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.451140 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.133s	user 0.102s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590345,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":410,"lbm_read_time_us":10010,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26372,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:04.451725 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:04.497959 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.046s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13344,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.498742 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.630869 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.132s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487815,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":159,"lbm_read_time_us":8966,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20953,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":1500}
I20260812 06:20:04.631677 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:04.687616 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.056s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19167,"lbm_writes_lt_1ms":303,"mutex_wait_us":44,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.688194 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:04.701359 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.701958 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.836614 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.134s	user 0.100s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":8495,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25772,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:20:04.837519 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:04.879134 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.041s	user 0.035s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17824,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.879745 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:04.894879 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.895393 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:04.927775 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1305,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:04.928617 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling LogGCOp(6068a27dc0f645d9ba062fb493c20aa8): free 120553382 bytes of WAL
I20260812 06:20:04.928898 12686 log_reader.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8: removed 12 log segments from log reader
I20260812 06:20:04.928959 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000013 (ops 61-65)
I20260812 06:20:04.928997 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000014 (ops 66-70)
I20260812 06:20:04.929028 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000015 (ops 71-74)
I20260812 06:20:04.929064 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000016 (ops 75-79)
I20260812 06:20:04.929086 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000017 (ops 80-84)
I20260812 06:20:04.929111 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000018 (ops 85-89)
I20260812 06:20:04.929145 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000019 (ops 90-94)
I20260812 06:20:04.929172 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000020 (ops 95-98)
I20260812 06:20:04.929207 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000021 (ops 99-103)
I20260812 06:20:04.929234 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000022 (ops 104-108)
I20260812 06:20:04.929267 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000023 (ops 109-113)
I20260812 06:20:04.929291 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000024 (ops 114-118)
I20260812 06:20:04.960559 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: LogGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:04.961061 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8): 463 bytes on disk
I20260812 06:20:04.961722 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.962445 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:04.988193 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.026s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.988749 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling LogGCOp(6068a27dc0f645d9ba062fb493c20aa8): free 11564875 bytes of WAL
I20260812 06:20:04.988970 12686 log_reader.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8: removed 1 log segments from log reader
I20260812 06:20:04.989010 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000025 (ops 119-122)
I20260812 06:20:04.991228 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: LogGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:04.991591 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:05.003942 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.004544 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:05.194824 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.190s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795408,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":281,"lbm_read_time_us":12148,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38675,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:20:05.195535 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=14.095187
I20260812 06:20:05.248212 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.052s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21482,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.248857 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:05.263146 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.263712 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:05.419833 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.156s	user 0.119s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1151,"lbm_read_time_us":9915,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30282,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:20:05.420428 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=11.118625
I20260812 06:20:05.461315 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.041s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18090,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.461944 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:05.475104 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5033,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.475592 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:05.670100 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.194s	user 0.117s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1419,"lbm_read_time_us":11435,"lbm_reads_lt_1ms":472,"lbm_write_time_us":33219,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":80640,"update_count":2000}
I20260812 06:20:05.670814 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=14.095187
I20260812 06:20:05.730315 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.059s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24334,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.730885 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:05.743134 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.744046 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:05.937109 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.193s	user 0.129s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":349,"lbm_read_time_us":14331,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32080,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60160,"update_count":2500}
I20260812 06:20:05.937953 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=14.095187
I20260812 06:20:06.017191 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.079s	user 0.036s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":27980,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.018035 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:06.030824 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.031443 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:06.212769 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.181s	user 0.119s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692760,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":13495,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31516,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:20:06.213850 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=11.118625
I20260812 06:20:06.261897 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.048s	user 0.035s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":23093,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.262476 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:06.278546 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5325,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.279208 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:06.449262 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.170s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590339,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":775,"lbm_read_time_us":9925,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26758,"lbm_writes_lt_1ms":443,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:20:06.450016 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=14.095187
I20260812 06:20:06.505824 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.056s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24610,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.506402 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=2.188937
I20260812 06:20:06.520015 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4660,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.521322 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:06.553121 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushMRSOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.032s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234476,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1529,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1951,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:06.554217 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling LogGCOp(6068a27dc0f645d9ba062fb493c20aa8): free 120553609 bytes of WAL
I20260812 06:20:06.554504 12686 log_reader.cc:385] T 6068a27dc0f645d9ba062fb493c20aa8: removed 12 log segments from log reader
I20260812 06:20:06.554551 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000026 (ops 123-127)
I20260812 06:20:06.554581 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000027 (ops 128-132)
I20260812 06:20:06.554646 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000028 (ops 133-136)
I20260812 06:20:06.554689 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000029 (ops 137-141)
I20260812 06:20:06.554733 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000030 (ops 142-146)
I20260812 06:20:06.554773 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000031 (ops 147-151)
I20260812 06:20:06.554813 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000032 (ops 152-156)
I20260812 06:20:06.554876 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000033 (ops 157-161)
I20260812 06:20:06.554919 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000034 (ops 162-166)
I20260812 06:20:06.554944 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000035 (ops 167-171)
I20260812 06:20:06.554984 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000036 (ops 172-176)
I20260812 06:20:06.555025 12686 log.cc:1079] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/6068a27dc0f645d9ba062fb493c20aa8/wal-000000037 (ops 177-180)
I20260812 06:20:06.581207 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: LogGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:06.581852 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8): 472 bytes on disk
I20260812 06:20:06.582505 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: UndoDeltaBlockGCOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:20:06.583087 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=3.181125
I20260812 06:20:06.599236 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":6242,"lbm_writes_lt_1ms":131,"mutex_wait_us":44,"reinsert_count":0,"update_count":640}
I20260812 06:20:06.599814 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.196750
I20260812 06:20:06.624217 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.024s	user 0.011s	sys 0.011s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:06.625162 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:06.864399 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.239s	user 0.162s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":887,"lbm_read_time_us":14002,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42266,"lbm_writes_lt_1ms":743,"mutex_wait_us":48,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":31616,"thread_start_us":130,"threads_started":1,"update_count":3500}
I20260812 06:20:06.865399 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=15.087375
I20260812 06:20:06.932688 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.067s	user 0.038s	sys 0.026s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":25722,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:06.933576 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=3.181125
I20260812 06:20:06.951136 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":5333389,"delete_count":0,"lbm_write_time_us":7060,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:20:06.951651 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.196750
I20260812 06:20:06.959259 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.007s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2690,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:20:06.959841 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=1.000000
I20260812 06:20:07.105222 12560 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.343s	user 1.977s	sys 0.159s
I20260812 06:20:07.162796 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: MajorDeltaCompactionOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.203s	user 0.153s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795252,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":14137,"lbm_reads_lt_1ms":669,"lbm_write_time_us":38152,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:20:07.163336 12762 maintenance_manager.cc:419] P d903ee4346d94392bbc7dae61111442a: Scheduling FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8): perf score=10.126437
I20260812 06:20:07.180395 12560 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.075s	user 0.001s	sys 0.000s
I20260812 06:20:07.181119 12560 tablet_server.cc:179] TabletServer@127.12.68.1:0 shutting down...
I20260812 06:20:07.210750 12686 maintenance_manager.cc:643] P d903ee4346d94392bbc7dae61111442a: FlushDeltaMemStoresOp(6068a27dc0f645d9ba062fb493c20aa8) complete. Timing: real 0.047s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16870,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.211846 12560 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:07.212435 12560 tablet_replica.cc:333] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a: stopping tablet replica
I20260812 06:20:07.212638 12560 raft_consensus.cc:2243] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.212843 12560 raft_consensus.cc:2272] T 6068a27dc0f645d9ba062fb493c20aa8 P d903ee4346d94392bbc7dae61111442a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.228823 12560 tablet_server.cc:196] TabletServer@127.12.68.1:0 shutdown complete.
I20260812 06:20:07.234812 12560 master.cc:562] Master@127.12.68.62:42717 shutting down...
I20260812 06:20:07.239060 12560 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.239253 12560 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.239379 12560 tablet_replica.cc:333] T 00000000000000000000000000000000 P 460969a19e3c4bbdb7c9ef4499496524: stopping tablet replica
I20260812 06:20:07.252441 12560 master.cc:584] Master@127.12.68.62:42717 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5937 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:07.349524 12560 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.68.62:46463
I20260812 06:20:07.350013 12560 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:07.352797 12797 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:20:07.352835 12799 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:20:07.352874 12560 server_base.cc:1061] running on GCE node
W20260812 06:20:07.352835 12795 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:20:07.353288 12560 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:07.353338 12560 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:20:07.353353 12560 hybrid_clock.cc:648] HybridClock initialized: now 1786515607353354 us; error 0 us; skew 500 ppm
I20260812 06:20:07.354374 12560 webserver.cc:533] Webserver started at http://127.12.68.62:43701/ using document root <none> and password file <none>
I20260812 06:20:07.354534 12560 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:07.354616 12560 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:07.354715 12560 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:07.355207 12560 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/master-0-root/instance:
uuid: "c31455f740764d4bb1fb532d15d0bddb"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-g350"
I20260812 06:20:07.356987 12560 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:07.358362 12805 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:20:07.358824 12560 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:20:07.358961 12560 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/master-0-root
uuid: "c31455f740764d4bb1fb532d15d0bddb"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-g350"
I20260812 06:20:07.359079 12560 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-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:20:07.377756 12560 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:07.378526 12560 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:07.385515 12560 rpc_server.cc:307] RPC server started. Bound to: 127.12.68.62:46463
I20260812 06:20:07.388746 12863 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.68.62:46463 every 8 connection(s)
I20260812 06:20:07.389086 12864 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:20:07.396585 12864 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb: Bootstrap starting.
I20260812 06:20:07.397787 12864 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:07.399645 12864 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb: No bootstrap required, opened a new log
I20260812 06:20:07.400450 12864 raft_consensus.cc:359] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER }
I20260812 06:20:07.400594 12864 raft_consensus.cc:385] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:07.400624 12864 raft_consensus.cc:740] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c31455f740764d4bb1fb532d15d0bddb, State: Initialized, Role: FOLLOWER
I20260812 06:20:07.400825 12864 consensus_queue.cc:260] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [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: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER }
I20260812 06:20:07.400923 12864 raft_consensus.cc:399] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:07.401057 12864 raft_consensus.cc:493] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:07.401121 12864 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:07.402740 12864 raft_consensus.cc:515] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER }
I20260812 06:20:07.403021 12864 leader_election.cc:304] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [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: c31455f740764d4bb1fb532d15d0bddb; no voters: 
I20260812 06:20:07.403347 12864 leader_election.cc:290] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:07.403594 12867 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:07.403863 12867 raft_consensus.cc:697] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 1 LEADER]: Becoming Leader. State: Replica: c31455f740764d4bb1fb532d15d0bddb, State: Running, Role: LEADER
I20260812 06:20:07.403990 12864 sys_catalog.cc:565] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:07.404062 12867 consensus_queue.cc:237] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [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: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER }
I20260812 06:20:07.404701 12869 sys_catalog.cc:455] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [sys.catalog]: SysCatalogTable state changed. Reason: New leader c31455f740764d4bb1fb532d15d0bddb. Latest consensus state: current_term: 1 leader_uuid: "c31455f740764d4bb1fb532d15d0bddb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER } }
I20260812 06:20:07.404858 12869 sys_catalog.cc:458] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:07.405019 12868 sys_catalog.cc:455] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c31455f740764d4bb1fb532d15d0bddb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c31455f740764d4bb1fb532d15d0bddb" member_type: VOTER } }
I20260812 06:20:07.405129 12868 sys_catalog.cc:458] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:07.405500 12876 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:07.406311 12876 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:07.406807 12560 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:07.408574 12876 catalog_manager.cc:1383] Generated new cluster ID: 07785fd3f8474a46bc8ddac3ea5b620b
I20260812 06:20:07.408649 12876 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:07.423341 12876 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:07.423990 12876 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:07.441644 12876 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb: Generated new TSK 0
I20260812 06:20:07.441871 12876 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:07.471800 12560 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:07.474447 12890 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:20:07.474560 12892 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:20:07.474766 12560 server_base.cc:1061] running on GCE node
W20260812 06:20:07.474560 12888 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:20:07.475108 12560 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:07.475167 12560 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:20:07.475184 12560 hybrid_clock.cc:648] HybridClock initialized: now 1786515607475184 us; error 0 us; skew 500 ppm
I20260812 06:20:07.476217 12560 webserver.cc:533] Webserver started at http://127.12.68.1:42805/ using document root <none> and password file <none>
I20260812 06:20:07.476397 12560 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:07.476441 12560 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:07.476500 12560 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:07.476905 12560 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/instance:
uuid: "3a30db7b41d24c93b24f4bbffafbe51b"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-g350"
I20260812 06:20:07.478700 12560 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:07.479864 12899 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:20:07.480216 12560 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:07.480324 12560 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root
uuid: "3a30db7b41d24c93b24f4bbffafbe51b"
format_stamp: "Formatted at 2026-08-12 06:20:07 on dist-test-slave-g350"
I20260812 06:20:07.480407 12560 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-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:20:07.490145 12560 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:07.490543 12560 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:07.490823 12560 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:07.491339 12560 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:07.491380 12560 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:07.491442 12560 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:07.491482 12560 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:07.496739 12560 rpc_server.cc:307] RPC server started. Bound to: 127.12.68.1:41613
I20260812 06:20:07.497257 12974 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.68.1:41613 every 8 connection(s)
I20260812 06:20:07.511721 12975 heartbeater.cc:344] Connected to a master server at 127.12.68.62:46463
I20260812 06:20:07.512030 12975 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:07.512434 12975 heartbeater.cc:507] Master 127.12.68.62:46463 requested a full tablet report, sending...
I20260812 06:20:07.513760 12823 ts_manager.cc:194] Registered new tserver with Master: 3a30db7b41d24c93b24f4bbffafbe51b (127.12.68.1:41613)
I20260812 06:20:07.514533 12560 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017083673s
I20260812 06:20:07.514817 12823 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59170
I20260812 06:20:07.524765 12823 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59174:
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:20:07.534857 12931 tablet_service.cc:1511] Processing CreateTablet for tablet 5ed21da8d8f341b689cdf9e13b9484bb (DEFAULT_TABLE table=heavy-update-compaction-test [id=01d9156095034c11a345ccb4444526d8]), partition=
I20260812 06:20:07.535142 12931 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5ed21da8d8f341b689cdf9e13b9484bb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:07.537544 12990 tablet_bootstrap.cc:492] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Bootstrap starting.
I20260812 06:20:07.538554 12990 tablet_bootstrap.cc:654] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:07.539731 12990 tablet_bootstrap.cc:492] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: No bootstrap required, opened a new log
I20260812 06:20:07.539886 12990 ts_tablet_manager.cc:1403] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:07.540418 12990 raft_consensus.cc:359] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3a30db7b41d24c93b24f4bbffafbe51b" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 41613 } }
I20260812 06:20:07.540561 12990 raft_consensus.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:07.540616 12990 raft_consensus.cc:740] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3a30db7b41d24c93b24f4bbffafbe51b, State: Initialized, Role: FOLLOWER
I20260812 06:20:07.540755 12990 consensus_queue.cc:260] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [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: "3a30db7b41d24c93b24f4bbffafbe51b" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 41613 } }
I20260812 06:20:07.540834 12990 raft_consensus.cc:399] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:07.540896 12990 raft_consensus.cc:493] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:07.540954 12990 raft_consensus.cc:3060] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:07.541801 12990 raft_consensus.cc:515] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3a30db7b41d24c93b24f4bbffafbe51b" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 41613 } }
I20260812 06:20:07.541990 12990 leader_election.cc:304] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [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: 3a30db7b41d24c93b24f4bbffafbe51b; no voters: 
I20260812 06:20:07.542266 12990 leader_election.cc:290] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:07.542438 12992 raft_consensus.cc:2804] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:07.542670 12975 heartbeater.cc:499] Master 127.12.68.62:46463 was elected leader, sending a full tablet report...
I20260812 06:20:07.542667 12990 ts_tablet_manager.cc:1434] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:20:07.542670 12992 raft_consensus.cc:697] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 1 LEADER]: Becoming Leader. State: Replica: 3a30db7b41d24c93b24f4bbffafbe51b, State: Running, Role: LEADER
I20260812 06:20:07.542963 12992 consensus_queue.cc:237] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [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: "3a30db7b41d24c93b24f4bbffafbe51b" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 41613 } }
I20260812 06:20:07.544497 12823 catalog_manager.cc:5719] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b reported cstate change: term changed from 0 to 1, leader changed from <none> to 3a30db7b41d24c93b24f4bbffafbe51b (127.12.68.1). New cstate: current_term: 1 leader_uuid: "3a30db7b41d24c93b24f4bbffafbe51b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3a30db7b41d24c93b24f4bbffafbe51b" member_type: VOTER last_known_addr { host: "127.12.68.1" port: 41613 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:07.606855 12560 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.015s	sys 0.008s
I20260812 06:20:07.748157 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=15.086190
I20260812 06:20:07.891734 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.143s	user 0.102s	sys 0.039s Metrics: {"bytes_written":11897251,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":984,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35788,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:20:07.892589 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb): free 20743880 bytes of WAL
I20260812 06:20:07.892930 12905 log_reader.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb: removed 2 log segments from log reader
I20260812 06:20:07.892998 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000001 (ops 1-6)
I20260812 06:20:07.893042 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000002 (ops 7-11)
I20260812 06:20:07.898489 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:20:07.899050 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:07.916548 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.017s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.917037 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:08.076540 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.159s	user 0.103s	sys 0.056s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262038,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":728,"lbm_read_time_us":12831,"lbm_reads_lt_1ms":458,"lbm_write_time_us":27701,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":402,"threads_started":5,"update_count":1950}
I20260812 06:20:08.077282 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:08.135128 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.057s	user 0.025s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21766,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:08.135797 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb): 12719217 bytes on disk
I20260812 06:20:08.136471 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:20:08.137012 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:08.157219 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.158015 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:08.324720 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.165s	user 0.093s	sys 0.072s 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":613,"lbm_read_time_us":11491,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25222,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:08.325476 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:08.358889 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14126,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:08.360025 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:08.371079 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.371578 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:08.515401 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.144s	user 0.105s	sys 0.038s 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":203,"lbm_read_time_us":10106,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25044,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:20:08.516206 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:08.569468 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.053s	user 0.032s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17312,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:08.570065 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:08.580912 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.581435 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:08.705698 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.124s	user 0.096s	sys 0.028s 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":311,"lbm_read_time_us":9362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23661,"lbm_writes_lt_1ms":443,"mutex_wait_us":161,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:20:08.706526 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:08.762919 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.056s	user 0.039s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:08.764006 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:08.776053 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.776714 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:08.911357 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.134s	user 0.106s	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":422,"lbm_read_time_us":9837,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25518,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:20:08.912072 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:08.976423 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.064s	user 0.024s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19402,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:08.977077 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:08.988500 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.989216 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:09.145874 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.156s	user 0.104s	sys 0.052s 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":762,"lbm_read_time_us":13677,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23244,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2000}
I20260812 06:20:09.146443 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:09.199079 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.052s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19591,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.199607 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:09.211550 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.212167 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:09.348131 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.136s	user 0.093s	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":256,"lbm_read_time_us":9355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28537,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2000}
I20260812 06:20:09.348759 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=10.126437
I20260812 06:20:09.402783 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.054s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20859,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.403344 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:09.414953 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.415660 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:09.446023 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.030s	user 0.021s	sys 0.005s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:09.447263 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb): free 120553380 bytes of WAL
I20260812 06:20:09.447613 12905 log_reader.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb: removed 12 log segments from log reader
I20260812 06:20:09.447669 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000003 (ops 12-16)
I20260812 06:20:09.447705 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000004 (ops 17-20)
I20260812 06:20:09.447777 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000005 (ops 21-25)
I20260812 06:20:09.447822 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000006 (ops 26-30)
I20260812 06:20:09.448055 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000007 (ops 31-35)
I20260812 06:20:09.448160 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000008 (ops 36-40)
I20260812 06:20:09.448184 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000009 (ops 41-45)
I20260812 06:20:09.448242 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000010 (ops 46-50)
I20260812 06:20:09.448278 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000011 (ops 51-54)
I20260812 06:20:09.448320 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000012 (ops 55-59)
I20260812 06:20:09.448362 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000013 (ops 60-64)
I20260812 06:20:09.448405 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000014 (ops 65-69)
I20260812 06:20:09.477651 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:09.478174 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb): 482 bytes on disk
I20260812 06:20:09.478665 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.479223 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=3.181125
I20260812 06:20:09.493635 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:09.494182 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb): free 12017932 bytes of WAL
I20260812 06:20:09.494452 12905 log_reader.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb: removed 1 log segments from log reader
I20260812 06:20:09.494500 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000015 (ops 70-74)
I20260812 06:20:09.496863 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:09.497326 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:09.508750 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.509531 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:09.693411 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.184s	user 0.142s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":271,"lbm_read_time_us":12177,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35866,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27136,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:20:09.694216 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:09.747470 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.053s	user 0.024s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24216,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.748167 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:09.768347 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.020s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.768934 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:09.934103 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.165s	user 0.122s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":11744,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31398,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:09.934864 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:10.016728 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.082s	user 0.029s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28491,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.017330 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:10.029842 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.030627 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:10.236894 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.206s	user 0.150s	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":327,"lbm_read_time_us":12965,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37230,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2500}
I20260812 06:20:10.237450 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:10.301019 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.063s	user 0.027s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26035,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.301834 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:10.313203 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.313819 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:10.510227 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.196s	user 0.147s	sys 0.049s 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":215,"lbm_read_time_us":13795,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34275,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32512,"update_count":2500}
I20260812 06:20:10.513863 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:10.576588 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.062s	user 0.036s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.577319 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:10.589481 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.590139 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:10.782130 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.192s	user 0.135s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":13194,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31029,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:20:10.783116 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:10.845698 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.062s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24490,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.846249 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:10.868984 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.023s	user 0.005s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.869656 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:11.067288 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.197s	user 0.132s	sys 0.060s 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":663,"lbm_read_time_us":12861,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30911,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:20:11.068138 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:11.122910 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.055s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21147,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.123449 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:11.135318 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.005s	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:20:11.136009 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:11.186643 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.050s	user 0.044s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1567,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2244,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:11.187359 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb): free 129320537 bytes of WAL
I20260812 06:20:11.187597 12905 log_reader.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb: removed 13 log segments from log reader
I20260812 06:20:11.187638 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000016 (ops 75-79)
I20260812 06:20:11.187667 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000017 (ops 80-84)
I20260812 06:20:11.187713 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000018 (ops 85-88)
I20260812 06:20:11.187758 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000019 (ops 89-93)
I20260812 06:20:11.187814 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000020 (ops 94-98)
I20260812 06:20:11.187857 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000021 (ops 99-103)
I20260812 06:20:11.187885 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000022 (ops 104-108)
I20260812 06:20:11.187947 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000023 (ops 109-112)
I20260812 06:20:11.187986 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000024 (ops 113-117)
I20260812 06:20:11.188026 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000025 (ops 118-122)
I20260812 06:20:11.188066 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000026 (ops 123-127)
I20260812 06:20:11.188107 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000027 (ops 128-132)
I20260812 06:20:11.188146 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000028 (ops 133-137)
I20260812 06:20:11.215776 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:11.216341 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb): 493 bytes on disk
I20260812 06:20:11.216971 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:20:11.217653 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:11.241103 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.023s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":7366,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:20:11.241745 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:11.254396 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4758,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:20:11.255692 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:11.526188 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.270s	user 0.187s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3168,"lbm_read_time_us":17617,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46356,"lbm_writes_lt_1ms":743,"mutex_wait_us":1971,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24064,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:20:11.526814 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=18.063937
I20260812 06:20:11.591377 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.064s	user 0.032s	sys 0.029s Metrics: {"bytes_written":20512322,"delete_count":0,"lbm_write_time_us":28281,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.591943 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:11.603771 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.604278 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:11.831740 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.227s	user 0.149s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1013,"lbm_read_time_us":15863,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34569,"lbm_writes_lt_1ms":643,"mutex_wait_us":130,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":3000}
I20260812 06:20:11.832617 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=16.079562
I20260812 06:20:11.892452 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.060s	user 0.040s	sys 0.013s Metrics: {"bytes_written":18091890,"delete_count":0,"lbm_write_time_us":25445,"lbm_writes_lt_1ms":444,"reinsert_count":0,"update_count":2205}
I20260812 06:20:11.893118 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.196750
I20260812 06:20:11.905696 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2830884,"delete_count":0,"lbm_write_time_us":3082,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:11.906241 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:11.916469 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3832,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.917001 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:12.137789 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.221s	user 0.158s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877179,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":395,"lbm_read_time_us":16127,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36190,"lbm_writes_lt_1ms":643,"mutex_wait_us":90,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":3000}
I20260812 06:20:12.138928 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:12.196657 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.057s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24790,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.197361 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:12.368988 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.171s	user 0.107s	sys 0.059s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":974,"lbm_read_time_us":9930,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28128,"lbm_writes_lt_1ms":443,"mutex_wait_us":599,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:20:12.369863 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=11.118625
I20260812 06:20:12.416347 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.046s	user 0.025s	sys 0.017s Metrics: {"bytes_written":13004907,"delete_count":0,"lbm_write_time_us":16839,"lbm_writes_lt_1ms":320,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1585}
I20260812 06:20:12.416889 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:12.429407 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:20:12.430044 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:12.440173 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3664,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.440784 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:12.639562 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.198s	user 0.129s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":530,"lbm_read_time_us":10006,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31557,"lbm_writes_lt_1ms":543,"mutex_wait_us":157,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:12.640158 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=11.118625
I20260812 06:20:12.683338 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.043s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17598,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:12.684161 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:12.708897 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.025s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.709409 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:12.720351 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.720925 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:12.753960 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushMRSOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1593,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1592,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1792}
I20260812 06:20:12.754873 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb): free 111786515 bytes of WAL
I20260812 06:20:12.755170 12905 log_reader.cc:385] T 5ed21da8d8f341b689cdf9e13b9484bb: removed 11 log segments from log reader
I20260812 06:20:12.755236 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000029 (ops 138-142)
I20260812 06:20:12.755278 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000030 (ops 143-147)
I20260812 06:20:12.755314 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000031 (ops 148-152)
I20260812 06:20:12.755353 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000032 (ops 153-156)
I20260812 06:20:12.755376 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000033 (ops 157-161)
I20260812 06:20:12.755399 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000034 (ops 162-166)
I20260812 06:20:12.755434 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000035 (ops 167-171)
I20260812 06:20:12.755467 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000036 (ops 172-176)
I20260812 06:20:12.755497 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000037 (ops 177-181)
I20260812 06:20:12.755527 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000038 (ops 182-186)
I20260812 06:20:12.755558 12905 log.cc:1079] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: Deleting log segment in path: /tmp/dist-test-taskANrwKP/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515601400797-12560-0/minicluster-data/ts-0-root/wals/5ed21da8d8f341b689cdf9e13b9484bb/wal-000000039 (ops 187-190)
I20260812 06:20:12.786691 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: LogGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:12.787190 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb): 447 bytes on disk
I20260812 06:20:12.787670 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: UndoDeltaBlockGCOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:12.788228 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=2.188937
I20260812 06:20:12.805018 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.805642 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=1.000000
I20260812 06:20:12.992657 12560 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.386s	user 1.918s	sys 0.226s
I20260812 06:20:13.026647 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: MajorDeltaCompactionOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.221s	user 0.147s	sys 0.073s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14104,"lbm_reads_lt_1ms":662,"lbm_write_time_us":41070,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:20:13.027154 12976 maintenance_manager.cc:419] P 3a30db7b41d24c93b24f4bbffafbe51b: Scheduling FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb): perf score=14.095187
I20260812 06:20:13.062348 12560 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.069s	user 0.002s	sys 0.000s
I20260812 06:20:13.062877 12560 tablet_server.cc:179] TabletServer@127.12.68.1:0 shutting down...
I20260812 06:20:13.072701 12905 maintenance_manager.cc:643] P 3a30db7b41d24c93b24f4bbffafbe51b: FlushDeltaMemStoresOp(5ed21da8d8f341b689cdf9e13b9484bb) complete. Timing: real 0.045s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20179,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:13.073840 12560 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:13.074097 12560 tablet_replica.cc:333] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b: stopping tablet replica
I20260812 06:20:13.074254 12560 raft_consensus.cc:2243] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.074442 12560 raft_consensus.cc:2272] T 5ed21da8d8f341b689cdf9e13b9484bb P 3a30db7b41d24c93b24f4bbffafbe51b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.088972 12560 tablet_server.cc:196] TabletServer@127.12.68.1:0 shutdown complete.
I20260812 06:20:13.099525 12560 master.cc:562] Master@127.12.68.62:46463 shutting down...
I20260812 06:20:13.102914 12560 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.103137 12560 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.103231 12560 tablet_replica.cc:333] T 00000000000000000000000000000000 P c31455f740764d4bb1fb532d15d0bddb: stopping tablet replica
I20260812 06:20:13.116109 12560 master.cc:584] Master@127.12.68.62:46463 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5855 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11794 ms total)

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