[==========] 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:18:38.279377 24990 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.103.190:41885
I20260812 06:18:38.280428 24990 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:18:38.281041 24990 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:38.287806 24995 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:18:38.287887 24990 server_base.cc:1061] running on GCE node
W20260812 06:18:38.287801 24996 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:18:38.288076 24998 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:18:38.288573 24990 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.288691 24990 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:18:38.288740 24990 hybrid_clock.cc:648] HybridClock initialized: now 1786515518288737 us; error 0 us; skew 500 ppm
I20260812 06:18:38.290623 24990 webserver.cc:533] Webserver started at http://127.24.103.190:36297/ using document root <none> and password file <none>
I20260812 06:18:38.291196 24990 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.291281 24990 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.291548 24990 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.293339 24990 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/master-0-root/instance:
uuid: "8c0cbc981e124fe5b583cffd3141637c"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-6k22"
I20260812 06:18:38.296901 24990 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:18:38.298955 25003 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:18:38.299960 24990 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:18:38.300078 24990 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/master-0-root
uuid: "8c0cbc981e124fe5b583cffd3141637c"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-6k22"
I20260812 06:18:38.300173 24990 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-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:18:38.327064 24990 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.327804 24990 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:18:38.328001 24990 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.335785 24990 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.190:41885
I20260812 06:18:38.335834 25066 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.190:41885 every 8 connection(s)
I20260812 06:18:38.338055 25067 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:18:38.343550 25067 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: Bootstrap starting.
I20260812 06:18:38.346079 25067 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.347035 25067 log.cc:826] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:38.348820 25067 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: No bootstrap required, opened a new log
I20260812 06:18:38.351661 25067 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER }
I20260812 06:18:38.351835 25067 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.351907 25067 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c0cbc981e124fe5b583cffd3141637c, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.352511 25067 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [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: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER }
I20260812 06:18:38.352674 25067 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.352766 25067 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.352907 25067 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.353739 25067 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER }
I20260812 06:18:38.354177 25067 leader_election.cc:304] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [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: 8c0cbc981e124fe5b583cffd3141637c; no voters: 
I20260812 06:18:38.354496 25067 leader_election.cc:290] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.354642 25070 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.354913 25070 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 1 LEADER]: Becoming Leader. State: Replica: 8c0cbc981e124fe5b583cffd3141637c, State: Running, Role: LEADER
I20260812 06:18:38.355368 25070 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [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: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER }
I20260812 06:18:38.355592 25067 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:38.357203 25072 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8c0cbc981e124fe5b583cffd3141637c. Latest consensus state: current_term: 1 leader_uuid: "8c0cbc981e124fe5b583cffd3141637c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER } }
I20260812 06:18:38.357323 25072 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.357643 25071 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8c0cbc981e124fe5b583cffd3141637c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c0cbc981e124fe5b583cffd3141637c" member_type: VOTER } }
I20260812 06:18:38.357730 25071 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.357899 24990 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:38.359885 25088 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:38.359972 25088 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:38.360060 25085 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:38.360805 25085 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:38.365998 25085 catalog_manager.cc:1383] Generated new cluster ID: 2dd652cf5c204643b7d0e35b8ec9bb28
I20260812 06:18:38.366075 25085 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:38.388720 25085 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:38.390053 25085 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:38.405941 25085 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: Generated new TSK 0
I20260812 06:18:38.406839 25085 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:38.422819 24990 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:38.425803 25093 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:38.425824 25094 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:18:38.425832 25096 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:18:38.426198 24990 server_base.cc:1061] running on GCE node
I20260812 06:18:38.426474 24990 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.426518 24990 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:18:38.426534 24990 hybrid_clock.cc:648] HybridClock initialized: now 1786515518426535 us; error 0 us; skew 500 ppm
I20260812 06:18:38.427498 24990 webserver.cc:533] Webserver started at http://127.24.103.129:42707/ using document root <none> and password file <none>
I20260812 06:18:38.427719 24990 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.427827 24990 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.427909 24990 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.428273 24990 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/instance:
uuid: "50c04e9fb1204530963e164e018b9756"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-6k22"
I20260812 06:18:38.429788 24990 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:38.430809 25103 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:18:38.431077 24990 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:38.431150 24990 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root
uuid: "50c04e9fb1204530963e164e018b9756"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-6k22"
I20260812 06:18:38.431243 24990 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-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:18:38.437192 24990 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.437674 24990 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.438179 24990 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:38.439059 24990 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:38.439110 24990 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.439183 24990 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:38.439218 24990 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.446067 24990 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.129:46773
I20260812 06:18:38.446092 25176 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.129:46773 every 8 connection(s)
I20260812 06:18:38.460759 25177 heartbeater.cc:344] Connected to a master server at 127.24.103.190:41885
I20260812 06:18:38.461016 25177 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:38.461500 25177 heartbeater.cc:507] Master 127.24.103.190:41885 requested a full tablet report, sending...
I20260812 06:18:38.462926 25023 ts_manager.cc:194] Registered new tserver with Master: 50c04e9fb1204530963e164e018b9756 (127.24.103.129:46773)
I20260812 06:18:38.463354 24990 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016601233s
I20260812 06:18:38.464468 25023 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37064
I20260812 06:18:38.472888 25023 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37074:
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:18:38.487377 25136 tablet_service.cc:1511] Processing CreateTablet for tablet 732be624b03d4ff0bf003b3f1aa6416b (DEFAULT_TABLE table=heavy-update-compaction-test [id=5c7230e37772482f96791dbb95aec349]), partition=
I20260812 06:18:38.487922 25136 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 732be624b03d4ff0bf003b3f1aa6416b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:38.491000 25191 tablet_bootstrap.cc:492] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Bootstrap starting.
I20260812 06:18:38.492075 25191 tablet_bootstrap.cc:654] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.493212 25191 tablet_bootstrap.cc:492] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: No bootstrap required, opened a new log
I20260812 06:18:38.493323 25191 ts_tablet_manager.cc:1403] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:38.493794 25191 raft_consensus.cc:359] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50c04e9fb1204530963e164e018b9756" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 46773 } }
I20260812 06:18:38.493906 25191 raft_consensus.cc:385] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.493949 25191 raft_consensus.cc:740] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 50c04e9fb1204530963e164e018b9756, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.494115 25191 consensus_queue.cc:260] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [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: "50c04e9fb1204530963e164e018b9756" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 46773 } }
I20260812 06:18:38.494194 25191 raft_consensus.cc:399] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.494252 25191 raft_consensus.cc:493] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.494326 25191 raft_consensus.cc:3060] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.495293 25191 raft_consensus.cc:515] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50c04e9fb1204530963e164e018b9756" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 46773 } }
I20260812 06:18:38.495446 25191 leader_election.cc:304] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [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: 50c04e9fb1204530963e164e018b9756; no voters: 
I20260812 06:18:38.495821 25191 leader_election.cc:290] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.495923 25193 raft_consensus.cc:2804] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.496122 25193 raft_consensus.cc:697] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 1 LEADER]: Becoming Leader. State: Replica: 50c04e9fb1204530963e164e018b9756, State: Running, Role: LEADER
I20260812 06:18:38.496306 25191 ts_tablet_manager.cc:1434] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:38.496390 25193 consensus_queue.cc:237] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [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: "50c04e9fb1204530963e164e018b9756" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 46773 } }
I20260812 06:18:38.496464 25177 heartbeater.cc:499] Master 127.24.103.190:41885 was elected leader, sending a full tablet report...
I20260812 06:18:38.499768 25023 catalog_manager.cc:5719] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 reported cstate change: term changed from 0 to 1, leader changed from <none> to 50c04e9fb1204530963e164e018b9756 (127.24.103.129). New cstate: current_term: 1 leader_uuid: "50c04e9fb1204530963e164e018b9756" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50c04e9fb1204530963e164e018b9756" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 46773 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:38.562105 24990 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.010s	sys 0.016s
I20260812 06:18:38.697144 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=19.054940
I20260812 06:18:38.882741 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.185s	user 0.148s	sys 0.032s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":186,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":987,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45046,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":122,"threads_started":1,"update_count":1550}
I20260812 06:18:38.883996 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling LogGCOp(732be624b03d4ff0bf003b3f1aa6416b): free 20743831 bytes of WAL
I20260812 06:18:38.884341 25108 log_reader.cc:385] T 732be624b03d4ff0bf003b3f1aa6416b: removed 2 log segments from log reader
I20260812 06:18:38.884421 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000001 (ops 1-6)
I20260812 06:18:38.884501 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000002 (ops 7-11)
I20260812 06:18:38.888818 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: LogGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:38.889180 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:38.911856 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.023s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.912345 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:38.930773 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":8735,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.931267 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b): 16411397 bytes on disk
I20260812 06:18:38.932068 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.932500 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.096948 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.164s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":680,"lbm_read_time_us":12525,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27267,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":306,"threads_started":5,"update_count":2500}
I20260812 06:18:39.097559 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:39.141315 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.043s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.141932 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:39.152827 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.153250 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.282209 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.129s	user 0.112s	sys 0.016s 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":254,"lbm_read_time_us":8290,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25005,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:18:39.282809 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:39.315361 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.032s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14051,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.315939 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.424686 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.109s	user 0.081s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":94,"lbm_read_time_us":6549,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17916,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":1500}
I20260812 06:18:39.425354 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:39.470748 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.045s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.471299 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:39.486573 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.487246 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.628687 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.141s	user 0.113s	sys 0.028s 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":242,"lbm_read_time_us":10153,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24446,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":2000}
I20260812 06:18:39.629392 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:39.670522 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.041s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14105,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.671000 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:39.681915 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.682638 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.817145 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.134s	user 0.103s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1082,"lbm_read_time_us":9366,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24203,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:18:39.817788 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:39.854586 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.037s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19332,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.855038 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:39.865759 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.866294 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:39.992792 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.126s	user 0.093s	sys 0.032s 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":361,"lbm_read_time_us":9856,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22370,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:18:39.993393 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=10.126437
I20260812 06:18:40.034823 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.041s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18911,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.035379 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:40.049665 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.050211 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:40.085598 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.035s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1496,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:40.086688 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling LogGCOp(732be624b03d4ff0bf003b3f1aa6416b): free 112239312 bytes of WAL
I20260812 06:18:40.087314 25108 log_reader.cc:385] T 732be624b03d4ff0bf003b3f1aa6416b: removed 11 log segments from log reader
I20260812 06:18:40.087386 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000003 (ops 12-16)
I20260812 06:18:40.087448 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000004 (ops 17-21)
I20260812 06:18:40.087510 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000005 (ops 22-26)
I20260812 06:18:40.087581 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000006 (ops 27-30)
I20260812 06:18:40.087622 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000007 (ops 31-35)
I20260812 06:18:40.087735 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000008 (ops 36-40)
I20260812 06:18:40.087782 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000009 (ops 41-45)
I20260812 06:18:40.087822 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000010 (ops 46-50)
I20260812 06:18:40.087863 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000011 (ops 51-55)
I20260812 06:18:40.087901 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000012 (ops 56-60)
I20260812 06:18:40.087936 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000013 (ops 61-65)
I20260812 06:18:40.114389 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: LogGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:40.114918 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=5.165500
I20260812 06:18:40.132989 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":6646162,"delete_count":0,"lbm_write_time_us":7427,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:18:40.133453 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:40.140602 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1559102,"delete_count":0,"lbm_write_time_us":1927,"lbm_writes_lt_1ms":41,"reinsert_count":0,"update_count":190}
I20260812 06:18:40.141108 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:40.313407 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.172s	user 0.111s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1210,"lbm_read_time_us":13303,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32629,"lbm_writes_lt_1ms":643,"mutex_wait_us":735,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:18:40.314062 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:40.365990 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.052s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22250,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.366552 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:40.384090 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5963,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.384634 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:40.541245 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.156s	user 0.120s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":816,"lbm_read_time_us":8838,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31759,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:40.541934 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b): 461 bytes on disk
I20260812 06:18:40.542532 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.543251 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:40.593184 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.050s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":19487,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.593693 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:40.751753 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.158s	user 0.100s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672163,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":3085,"lbm_read_time_us":10448,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25705,"lbm_writes_lt_1ms":443,"mutex_wait_us":2496,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.752539 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=11.118625
I20260812 06:18:40.791188 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16278,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:40.791949 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:40.818822 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.027s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5049,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.819337 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:40.829572 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.830019 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:41.008594 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.178s	user 0.095s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":789,"lbm_read_time_us":11710,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28999,"lbm_writes_lt_1ms":543,"mutex_wait_us":318,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.009133 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:41.060766 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.051s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19283,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.061228 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:41.073266 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.073813 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:41.235201 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.161s	user 0.125s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":9326,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29817,"lbm_writes_lt_1ms":543,"mutex_wait_us":126,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:41.236049 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:41.291327 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.055s	user 0.019s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.291882 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:41.304549 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.305011 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:41.459978 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.155s	user 0.114s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":11697,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31170,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:18:41.460672 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:41.509913 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.049s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":20048,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.510419 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:41.521595 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.522095 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:41.552650 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.030s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1464,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1615,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:41.553331 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling LogGCOp(732be624b03d4ff0bf003b3f1aa6416b): free 128414453 bytes of WAL
I20260812 06:18:41.553555 25108 log_reader.cc:385] T 732be624b03d4ff0bf003b3f1aa6416b: removed 13 log segments from log reader
I20260812 06:18:41.553614 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000014 (ops 66-70)
I20260812 06:18:41.553669 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000015 (ops 71-74)
I20260812 06:18:41.553735 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000016 (ops 75-79)
I20260812 06:18:41.553778 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000017 (ops 80-84)
I20260812 06:18:41.553817 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000018 (ops 85-88)
I20260812 06:18:41.553854 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000019 (ops 89-93)
I20260812 06:18:41.553893 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000020 (ops 94-98)
I20260812 06:18:41.553933 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000021 (ops 99-102)
I20260812 06:18:41.553972 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000022 (ops 103-107)
I20260812 06:18:41.554020 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000023 (ops 108-112)
I20260812 06:18:41.554060 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000024 (ops 113-116)
I20260812 06:18:41.554098 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000025 (ops 117-121)
I20260812 06:18:41.554136 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000026 (ops 122-126)
I20260812 06:18:41.581434 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: LogGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:41.581912 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=3.181125
I20260812 06:18:41.599079 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6809,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.599484 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:41.608773 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3549,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.609346 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b): 472 bytes on disk
I20260812 06:18:41.610016 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.610736 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:41.852391 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.241s	user 0.173s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":600,"lbm_read_time_us":13127,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42451,"lbm_writes_lt_1ms":743,"mutex_wait_us":100,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:41.854105 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=18.063937
I20260812 06:18:41.931520 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.077s	user 0.051s	sys 0.021s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31940,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.932135 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=3.181125
I20260812 06:18:41.953943 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.022s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7718,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.954444 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:41.965268 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.965770 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:42.186698 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.221s	user 0.126s	sys 0.081s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979626,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":742,"lbm_read_time_us":15116,"lbm_reads_lt_1ms":773,"lbm_write_time_us":38193,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":3500}
I20260812 06:18:42.187351 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=18.063937
I20260812 06:18:42.238428 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":22756,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:42.238977 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:42.254717 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.255319 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:42.429890 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.174s	user 0.121s	sys 0.053s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":470,"lbm_read_time_us":12680,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32438,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":26240,"update_count":3000}
I20260812 06:18:42.430580 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:42.479736 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.049s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21399,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.480727 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:42.496335 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.496855 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:42.651223 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.154s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1493,"lbm_read_time_us":8468,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30927,"lbm_writes_lt_1ms":543,"mutex_wait_us":385,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:18:42.651937 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=14.095187
I20260812 06:18:42.701094 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.049s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21467,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.701793 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:42.849870 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.148s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":561,"lbm_read_time_us":8477,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25453,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:42.850572 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=11.118625
I20260812 06:18:42.887912 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.037s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15738,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:42.888723 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:42.903074 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.903678 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:42.940522 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushMRSOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.037s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1410,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:42.941388 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b): 463 bytes on disk
I20260812 06:18:42.941835 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: UndoDeltaBlockGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.942616 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=3.181125
I20260812 06:18:42.961350 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.019s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.961833 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling LogGCOp(732be624b03d4ff0bf003b3f1aa6416b): free 120553628 bytes of WAL
I20260812 06:18:42.962057 25108 log_reader.cc:385] T 732be624b03d4ff0bf003b3f1aa6416b: removed 12 log segments from log reader
I20260812 06:18:42.962117 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000027 (ops 127-131)
I20260812 06:18:42.962177 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000028 (ops 132-136)
I20260812 06:18:42.962234 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000029 (ops 137-141)
I20260812 06:18:42.962275 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000030 (ops 142-146)
I20260812 06:18:42.962313 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000031 (ops 147-151)
I20260812 06:18:42.962350 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000032 (ops 152-156)
I20260812 06:18:42.962386 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000033 (ops 157-161)
I20260812 06:18:42.962423 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000034 (ops 162-166)
I20260812 06:18:42.962459 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000035 (ops 167-170)
I20260812 06:18:42.962495 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000036 (ops 171-175)
I20260812 06:18:42.962531 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000037 (ops 176-180)
I20260812 06:18:42.962566 25108 log.cc:1079] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/732be624b03d4ff0bf003b3f1aa6416b/wal-000000038 (ops 181-184)
I20260812 06:18:42.988709 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: LogGCOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:42.989077 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:43.007372 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.018s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.007918 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:43.021514 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5053,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.021991 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:43.256131 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.234s	user 0.136s	sys 0.095s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2658,"lbm_read_time_us":16740,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36615,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:18:43.256940 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=18.063937
I20260812 06:18:43.325970 24990 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.764s	user 1.760s	sys 0.151s
I20260812 06:18:43.329735 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.073s	user 0.033s	sys 0.027s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25787,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:43.330147 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=2.188937
I20260812 06:18:43.339614 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: FlushDeltaMemStoresOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.340078 25178 maintenance_manager.cc:419] P 50c04e9fb1204530963e164e018b9756: Scheduling MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b): perf score=1.000000
I20260812 06:18:43.399694 24990 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.005s	sys 0.000s
I20260812 06:18:43.400452 24990 tablet_server.cc:179] TabletServer@127.24.103.129:0 shutting down...
I20260812 06:18:43.487151 25108 maintenance_manager.cc:643] P 50c04e9fb1204530963e164e018b9756: MajorDeltaCompactionOp(732be624b03d4ff0bf003b3f1aa6416b) complete. Timing: real 0.147s	user 0.072s	sys 0.071s Metrics: {"cfile_cache_hit":246,"cfile_cache_hit_bytes":10054377,"cfile_cache_miss":386,"cfile_cache_miss_bytes":18822726,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"dirs.run_cpu_time_us":653,"dirs.run_wall_time_us":2929,"lbm_read_time_us":7279,"lbm_reads_lt_1ms":418,"lbm_write_time_us":29424,"lbm_writes_lt_1ms":643,"mutex_wait_us":128,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":134784,"update_count":3000}
I20260812 06:18:43.488212 24990 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:43.488651 24990 tablet_replica.cc:333] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756: stopping tablet replica
I20260812 06:18:43.488933 24990 raft_consensus.cc:2243] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.489195 24990 raft_consensus.cc:2272] T 732be624b03d4ff0bf003b3f1aa6416b P 50c04e9fb1204530963e164e018b9756 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.504601 24990 tablet_server.cc:196] TabletServer@127.24.103.129:0 shutdown complete.
I20260812 06:18:43.539350 24990 master.cc:562] Master@127.24.103.190:41885 shutting down...
I20260812 06:18:43.543803 24990 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.543963 24990 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.544016 24990 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8c0cbc981e124fe5b583cffd3141637c: stopping tablet replica
I20260812 06:18:43.556164 24990 master.cc:584] Master@127.24.103.190:41885 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5367 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:43.657239 24990 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.103.190:32897
I20260812 06:18:43.657677 24990 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.659821 25218 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.659924 25221 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:18:43.659960 24990 server_base.cc:1061] running on GCE node
W20260812 06:18:43.659942 25219 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:18:43.660313 24990 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.660377 24990 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:18:43.660403 24990 hybrid_clock.cc:648] HybridClock initialized: now 1786515523660402 us; error 0 us; skew 500 ppm
I20260812 06:18:43.661208 24990 webserver.cc:533] Webserver started at http://127.24.103.190:38447/ using document root <none> and password file <none>
I20260812 06:18:43.661382 24990 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.661448 24990 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.661526 24990 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.661924 24990 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/master-0-root/instance:
uuid: "ae7970b84149436cab65bf4181f5b5aa"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-6k22"
I20260812 06:18:43.663527 24990 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:43.664517 25226 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:18:43.664759 24990 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.664851 24990 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/master-0-root
uuid: "ae7970b84149436cab65bf4181f5b5aa"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-6k22"
I20260812 06:18:43.664937 24990 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-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:18:43.675467 24990 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.675948 24990 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.680107 24990 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.190:32897
I20260812 06:18:43.685680 25294 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.190:32897 every 8 connection(s)
I20260812 06:18:43.686143 25295 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:18:43.687979 25295 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa: Bootstrap starting.
I20260812 06:18:43.688855 25295 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.689862 25295 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa: No bootstrap required, opened a new log
I20260812 06:18:43.690277 25295 raft_consensus.cc:359] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER }
I20260812 06:18:43.690385 25295 raft_consensus.cc:385] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.690436 25295 raft_consensus.cc:740] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae7970b84149436cab65bf4181f5b5aa, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.690595 25295 consensus_queue.cc:260] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [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: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER }
I20260812 06:18:43.690687 25295 raft_consensus.cc:399] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.690735 25295 raft_consensus.cc:493] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.690795 25295 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.691490 25295 raft_consensus.cc:515] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER }
I20260812 06:18:43.691668 25295 leader_election.cc:304] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [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: ae7970b84149436cab65bf4181f5b5aa; no voters: 
I20260812 06:18:43.691866 25295 leader_election.cc:290] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.691979 25299 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.692225 25299 raft_consensus.cc:697] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 1 LEADER]: Becoming Leader. State: Replica: ae7970b84149436cab65bf4181f5b5aa, State: Running, Role: LEADER
I20260812 06:18:43.692313 25295 sys_catalog.cc:565] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.692369 25299 consensus_queue.cc:237] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [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: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER }
I20260812 06:18:43.692795 25301 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ae7970b84149436cab65bf4181f5b5aa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER } }
I20260812 06:18:43.692826 25302 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [sys.catalog]: SysCatalogTable state changed. Reason: New leader ae7970b84149436cab65bf4181f5b5aa. Latest consensus state: current_term: 1 leader_uuid: "ae7970b84149436cab65bf4181f5b5aa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7970b84149436cab65bf4181f5b5aa" member_type: VOTER } }
I20260812 06:18:43.692991 25302 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.692967 25301 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.693535 25307 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.694280 25307 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.694505 24990 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.696094 25307 catalog_manager.cc:1383] Generated new cluster ID: 56e2030e71594f6eb71a1f07b7a75a9e
I20260812 06:18:43.696152 25307 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.711210 25307 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.711800 25307 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.717785 25307 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa: Generated new TSK 0
I20260812 06:18:43.717940 25307 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.727281 24990 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.729385 25318 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.729403 25322 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:18:43.729408 25319 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:18:43.729667 24990 server_base.cc:1061] running on GCE node
I20260812 06:18:43.729821 24990 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.729873 24990 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:18:43.729889 24990 hybrid_clock.cc:648] HybridClock initialized: now 1786515523729889 us; error 0 us; skew 500 ppm
I20260812 06:18:43.730710 24990 webserver.cc:533] Webserver started at http://127.24.103.129:34027/ using document root <none> and password file <none>
I20260812 06:18:43.730891 24990 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.730943 24990 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.730995 24990 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.731353 24990 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/instance:
uuid: "2d292cd63ca841209be20118221687c3"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-6k22"
I20260812 06:18:43.732901 24990 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.733771 25328 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:18:43.734021 24990 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.734112 24990 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root
uuid: "2d292cd63ca841209be20118221687c3"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-6k22"
I20260812 06:18:43.734197 24990 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-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:18:43.743659 24990 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.743976 24990 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.744212 24990 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.744680 24990 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.744741 24990 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.744819 24990 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.744877 24990 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.749091 24990 rpc_server.cc:307] RPC server started. Bound to: 127.24.103.129:35241
I20260812 06:18:43.750128 25414 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.103.129:35241 every 8 connection(s)
I20260812 06:18:43.760013 25415 heartbeater.cc:344] Connected to a master server at 127.24.103.190:32897
I20260812 06:18:43.760128 25415 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.760389 25415 heartbeater.cc:507] Master 127.24.103.190:32897 requested a full tablet report, sending...
I20260812 06:18:43.761034 25248 ts_manager.cc:194] Registered new tserver with Master: 2d292cd63ca841209be20118221687c3 (127.24.103.129:35241)
I20260812 06:18:43.761745 25248 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47108
I20260812 06:18:43.761854 24990 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012142242s
I20260812 06:18:43.768677 25248 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47112:
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:18:43.777191 25367 tablet_service.cc:1511] Processing CreateTablet for tablet 4a55c6b608124746b4353638a878e057 (DEFAULT_TABLE table=heavy-update-compaction-test [id=41827135a4694301ab6de8b0be8f1416]), partition=
I20260812 06:18:43.777426 25367 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4a55c6b608124746b4353638a878e057. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.779367 25429 tablet_bootstrap.cc:492] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Bootstrap starting.
I20260812 06:18:43.780154 25429 tablet_bootstrap.cc:654] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.781106 25429 tablet_bootstrap.cc:492] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: No bootstrap required, opened a new log
I20260812 06:18:43.781178 25429 ts_tablet_manager.cc:1403] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:43.781635 25429 raft_consensus.cc:359] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d292cd63ca841209be20118221687c3" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 35241 } }
I20260812 06:18:43.781723 25429 raft_consensus.cc:385] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.781746 25429 raft_consensus.cc:740] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2d292cd63ca841209be20118221687c3, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.781893 25429 consensus_queue.cc:260] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [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: "2d292cd63ca841209be20118221687c3" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 35241 } }
I20260812 06:18:43.781966 25429 raft_consensus.cc:399] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.782025 25429 raft_consensus.cc:493] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.782086 25429 raft_consensus.cc:3060] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.783046 25429 raft_consensus.cc:515] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d292cd63ca841209be20118221687c3" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 35241 } }
I20260812 06:18:43.783159 25429 leader_election.cc:304] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [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: 2d292cd63ca841209be20118221687c3; no voters: 
I20260812 06:18:43.783403 25429 leader_election.cc:290] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.783548 25432 raft_consensus.cc:2804] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.783794 25415 heartbeater.cc:499] Master 127.24.103.190:32897 was elected leader, sending a full tablet report...
I20260812 06:18:43.783804 25429 ts_tablet_manager.cc:1434] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:43.783849 25432 raft_consensus.cc:697] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 1 LEADER]: Becoming Leader. State: Replica: 2d292cd63ca841209be20118221687c3, State: Running, Role: LEADER
I20260812 06:18:43.784021 25432 consensus_queue.cc:237] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [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: "2d292cd63ca841209be20118221687c3" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 35241 } }
I20260812 06:18:43.785380 25248 catalog_manager.cc:5719] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2d292cd63ca841209be20118221687c3 (127.24.103.129). New cstate: current_term: 1 leader_uuid: "2d292cd63ca841209be20118221687c3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2d292cd63ca841209be20118221687c3" member_type: VOTER last_known_addr { host: "127.24.103.129" port: 35241 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.843451 24990 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.009s	sys 0.013s
I20260812 06:18:44.001205 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushMRSOp(4a55c6b608124746b4353638a878e057): perf score=20.047128
I20260812 06:18:44.170176 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushMRSOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.169s	user 0.117s	sys 0.047s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":159,"dirs.run_wall_time_us":611,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43943,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:44.170814 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling LogGCOp(4a55c6b608124746b4353638a878e057): free 20743831 bytes of WAL
I20260812 06:18:44.171034 25333 log_reader.cc:385] T 4a55c6b608124746b4353638a878e057: removed 2 log segments from log reader
I20260812 06:18:44.171079 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000001 (ops 1-6)
I20260812 06:18:44.171128 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000002 (ops 7-11)
I20260812 06:18:44.176681 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: LogGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:44.177098 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:44.193298 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.193948 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:44.355430 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":520,"lbm_read_time_us":10772,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30272,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":289,"threads_started":5,"update_count":2000}
I20260812 06:18:44.355935 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=10.126437
I20260812 06:18:44.401968 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.046s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20169,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.402485 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057): 20513817 bytes on disk
I20260812 06:18:44.402880 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.403249 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:44.425107 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.022s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.425590 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:44.587203 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.161s	user 0.091s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1214,"lbm_read_time_us":11534,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24434,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:44.587921 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=11.118625
I20260812 06:18:44.621788 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.034s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14075,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.622354 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:44.641340 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.019s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.641758 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:44.651151 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3568,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.651607 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:44.814903 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.163s	user 0.100s	sys 0.054s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1119,"lbm_read_time_us":10849,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31833,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:18:44.815490 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:44.870605 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.055s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24598,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.871182 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:44.887429 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.888089 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:45.036947 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.149s	user 0.122s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":9453,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31067,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:45.037495 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:45.095814 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.058s	user 0.017s	sys 0.040s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26449,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.096278 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:45.107613 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.108068 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:45.264819 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.157s	user 0.111s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":514,"lbm_read_time_us":10853,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30333,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:45.265506 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=12.110812
I20260812 06:18:45.309872 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.044s	user 0.022s	sys 0.020s Metrics: {"bytes_written":14276638,"delete_count":0,"lbm_write_time_us":19652,"lbm_writes_lt_1ms":351,"reinsert_count":0,"update_count":1740}
I20260812 06:18:45.310675 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=1.196750
I20260812 06:18:45.319905 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2297558,"delete_count":0,"lbm_write_time_us":2951,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:45.320401 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushMRSOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:45.360252 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushMRSOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.040s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1478,"drs_written":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:45.361871 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057): 447 bytes on disk
I20260812 06:18:45.362444 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.362980 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=3.181125
I20260812 06:18:45.376888 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.014s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4348810,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:45.377343 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling LogGCOp(4a55c6b608124746b4353638a878e057): free 115943221 bytes of WAL
I20260812 06:18:45.377557 25333 log_reader.cc:385] T 4a55c6b608124746b4353638a878e057: removed 11 log segments from log reader
I20260812 06:18:45.377616 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000003 (ops 12-16)
I20260812 06:18:45.377671 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000004 (ops 17-21)
I20260812 06:18:45.377729 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000005 (ops 22-26)
I20260812 06:18:45.377770 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000006 (ops 27-31)
I20260812 06:18:45.377836 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000007 (ops 32-36)
I20260812 06:18:45.377877 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000008 (ops 37-41)
I20260812 06:18:45.377915 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000009 (ops 42-46)
I20260812 06:18:45.377954 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000010 (ops 47-51)
I20260812 06:18:45.377990 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000011 (ops 52-56)
I20260812 06:18:45.378026 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000012 (ops 57-61)
I20260812 06:18:45.378064 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000013 (ops 62-66)
I20260812 06:18:45.403998 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: LogGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:45.404389 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:45.422552 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.018s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.423034 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:45.433049 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.433432 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:45.645936 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.212s	user 0.152s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":539,"lbm_read_time_us":15242,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38387,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:45.646400 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=18.063937
I20260812 06:18:45.703159 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.057s	user 0.018s	sys 0.035s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25350,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.703747 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:45.717161 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.717684 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:45.886185 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.168s	user 0.137s	sys 0.032s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":12371,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35550,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:18:45.886791 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:45.931008 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.044s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18966,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.931504 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:45.941974 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.942421 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:46.108112 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.165s	user 0.118s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":11708,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31851,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:46.108907 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=11.118625
I20260812 06:18:46.144133 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.035s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15907,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.144951 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:46.160228 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.160760 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:46.325794 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.165s	user 0.095s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":10540,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25400,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:46.326326 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:46.383080 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27707,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.383718 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:46.404650 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.021s	user 0.008s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.405433 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:46.605258 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.200s	user 0.105s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":12657,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30156,"lbm_writes_lt_1ms":543,"mutex_wait_us":295,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":2500}
I20260812 06:18:46.605809 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:46.660027 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.054s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21398,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.660490 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:46.672873 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.673353 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:46.864859 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.191s	user 0.114s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":10639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32007,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:18:46.865478 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:46.918028 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.052s	user 0.023s	sys 0.018s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19257,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.918529 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:46.930205 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.930704 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushMRSOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:46.965493 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushMRSOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":147,"dirs.run_wall_time_us":1353,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2077,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.966208 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling LogGCOp(4a55c6b608124746b4353638a878e057): free 133024388 bytes of WAL
I20260812 06:18:46.966463 25333 log_reader.cc:385] T 4a55c6b608124746b4353638a878e057: removed 13 log segments from log reader
I20260812 06:18:46.966549 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000014 (ops 67-71)
I20260812 06:18:46.966609 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000015 (ops 72-76)
I20260812 06:18:46.966646 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000016 (ops 77-81)
I20260812 06:18:46.966673 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000017 (ops 82-86)
I20260812 06:18:46.966706 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000018 (ops 87-90)
I20260812 06:18:46.966737 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000019 (ops 91-95)
I20260812 06:18:46.966775 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000020 (ops 96-100)
I20260812 06:18:46.966815 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000021 (ops 101-105)
I20260812 06:18:46.966856 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000022 (ops 106-110)
I20260812 06:18:46.966895 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000023 (ops 111-115)
I20260812 06:18:46.966934 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000024 (ops 116-120)
I20260812 06:18:46.966974 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000025 (ops 121-125)
I20260812 06:18:46.967015 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000026 (ops 126-130)
I20260812 06:18:46.999118 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: LogGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:46.999801 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=5.165500
I20260812 06:18:47.025161 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.025s	user 0.014s	sys 0.009s Metrics: {"bytes_written":6400018,"delete_count":0,"lbm_write_time_us":10478,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:18:47.025683 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057): 492 bytes on disk
I20260812 06:18:47.026091 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.026592 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:47.032718 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":1886,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:18:47.033118 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:47.279846 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.247s	user 0.181s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1174,"lbm_read_time_us":16455,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39038,"lbm_writes_lt_1ms":743,"mutex_wait_us":530,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:47.281039 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=18.063937
I20260812 06:18:47.354024 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.073s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26808,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.354491 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:47.365630 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.366146 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:47.567795 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.201s	user 0.159s	sys 0.041s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":718,"lbm_read_time_us":13126,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33690,"lbm_writes_lt_1ms":643,"mutex_wait_us":342,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:18:47.568668 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=17.071750
I20260812 06:18:47.631273 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.062s	user 0.025s	sys 0.020s Metrics: {"bytes_written":18707249,"delete_count":0,"lbm_write_time_us":22249,"lbm_writes_lt_1ms":459,"reinsert_count":0,"update_count":2280}
I20260812 06:18:47.631804 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=4.173312
I20260812 06:18:47.648371 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":5907732,"delete_count":0,"lbm_write_time_us":6443,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:47.648947 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:47.872184 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.223s	user 0.143s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":14794,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36122,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28672,"update_count":3000}
I20260812 06:18:47.873047 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=18.063937
I20260812 06:18:47.943195 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.070s	user 0.014s	sys 0.037s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26578,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.943751 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:47.954978 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.955778 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:48.163172 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.207s	user 0.126s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":954,"lbm_read_time_us":14874,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35230,"lbm_writes_lt_1ms":643,"mutex_wait_us":334,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:48.163970 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:48.227068 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.063s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25215,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.227641 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:48.237953 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.238420 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:48.420625 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.182s	user 0.119s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":185,"lbm_read_time_us":12987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30110,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2500}
I20260812 06:18:48.421257 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=14.095187
I20260812 06:18:48.481261 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.060s	user 0.018s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19012,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.481788 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=2.188937
I20260812 06:18:48.492281 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.492753 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushMRSOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:48.523780 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushMRSOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1399,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1447,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:48.524523 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057): perf score=1.000000
I20260812 06:18:48.711707 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: MajorDeltaCompactionOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.187s	user 0.133s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1321,"lbm_read_time_us":12399,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34464,"lbm_writes_lt_1ms":543,"mutex_wait_us":792,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:48.712324 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling LogGCOp(4a55c6b608124746b4353638a878e057): free 121006656 bytes of WAL
I20260812 06:18:48.712711 25333 log_reader.cc:385] T 4a55c6b608124746b4353638a878e057: removed 12 log segments from log reader
I20260812 06:18:48.712869 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000027 (ops 131-135)
I20260812 06:18:48.713027 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000028 (ops 136-140)
I20260812 06:18:48.713158 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000029 (ops 141-145)
I20260812 06:18:48.713297 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000030 (ops 146-150)
I20260812 06:18:48.713398 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000031 (ops 151-155)
I20260812 06:18:48.713503 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000032 (ops 156-160)
I20260812 06:18:48.713608 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000033 (ops 161-164)
I20260812 06:18:48.713675 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000034 (ops 165-169)
I20260812 06:18:48.713717 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000035 (ops 170-174)
I20260812 06:18:48.713786 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000036 (ops 175-179)
I20260812 06:18:48.713847 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000037 (ops 180-184)
I20260812 06:18:48.713905 25333 log.cc:1079] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: Deleting log segment in path: /tmp/dist-test-taskRcg2Y3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518268459-24990-0/minicluster-data/ts-0-root/wals/4a55c6b608124746b4353638a878e057/wal-000000038 (ops 185-189)
I20260812 06:18:48.732547 24990 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.889s	user 1.840s	sys 0.182s
I20260812 06:18:48.741081 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: LogGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.028s	user 0.003s	sys 0.024s Metrics: {}
I20260812 06:18:48.741524 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057): 473 bytes on disk
I20260812 06:18:48.741945 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: UndoDeltaBlockGCOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.742472 25416 maintenance_manager.cc:419] P 2d292cd63ca841209be20118221687c3: Scheduling FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057): perf score=18.063937
I20260812 06:18:48.758386 24990 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.025s	user 0.002s	sys 0.000s
I20260812 06:18:48.758984 24990 tablet_server.cc:179] TabletServer@127.24.103.129:0 shutting down...
I20260812 06:18:48.802603 25333 maintenance_manager.cc:643] P 2d292cd63ca841209be20118221687c3: FlushDeltaMemStoresOp(4a55c6b608124746b4353638a878e057) complete. Timing: real 0.060s	user 0.027s	sys 0.030s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":23097,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.803225 24990 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.803448 24990 tablet_replica.cc:333] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3: stopping tablet replica
I20260812 06:18:48.803617 24990 raft_consensus.cc:2243] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.803803 24990 raft_consensus.cc:2272] T 4a55c6b608124746b4353638a878e057 P 2d292cd63ca841209be20118221687c3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.806895 24990 tablet_server.cc:196] TabletServer@127.24.103.129:0 shutdown complete.
I20260812 06:18:48.809535 24990 master.cc:562] Master@127.24.103.190:32897 shutting down...
I20260812 06:18:48.812844 24990 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.812994 24990 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.813066 24990 tablet_replica.cc:333] T 00000000000000000000000000000000 P ae7970b84149436cab65bf4181f5b5aa: stopping tablet replica
I20260812 06:18:48.825284 24990 master.cc:584] Master@127.24.103.190:32897 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5265 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10634 ms total)

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