[==========] 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:23.690758 26500 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.225.62:35521
I20260812 06:18:23.691998 26500 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:23.692663 26500 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:23.699978 26510 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:23.700033 26500 server_base.cc:1061] running on GCE node
W20260812 06:18:23.699980 26507 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:23.700307 26508 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:23.700856 26500 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:23.700960 26500 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:23.700989 26500 hybrid_clock.cc:648] HybridClock initialized: now 1786515503700986 us; error 0 us; skew 500 ppm
I20260812 06:18:23.706470 26500 webserver.cc:533] Webserver started at http://127.25.225.62:33557/ using document root <none> and password file <none>
I20260812 06:18:23.707059 26500 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:23.707124 26500 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:23.707345 26500 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:23.709218 26500 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/master-0-root/instance:
uuid: "63135ad8d50b4ae58b3c2559a00bdb9b"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-mvvj"
I20260812 06:18:23.713181 26500 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:23.715668 26516 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:23.716920 26500 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:23.717087 26500 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/master-0-root
uuid: "63135ad8d50b4ae58b3c2559a00bdb9b"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-mvvj"
I20260812 06:18:23.717218 26500 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-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:23.732933 26500 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:23.733625 26500 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:23.733815 26500 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:23.741868 26500 rpc_server.cc:307] RPC server started. Bound to: 127.25.225.62:35521
I20260812 06:18:23.741881 26576 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.225.62:35521 every 8 connection(s)
I20260812 06:18:23.744314 26577 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:23.750097 26577 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: Bootstrap starting.
I20260812 06:18:23.752537 26577 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:23.753538 26577 log.cc:826] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:23.755435 26577 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: No bootstrap required, opened a new log
I20260812 06:18:23.758445 26577 raft_consensus.cc:359] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER }
I20260812 06:18:23.758618 26577 raft_consensus.cc:385] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:23.758692 26577 raft_consensus.cc:740] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 63135ad8d50b4ae58b3c2559a00bdb9b, State: Initialized, Role: FOLLOWER
I20260812 06:18:23.759322 26577 consensus_queue.cc:260] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [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: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER }
I20260812 06:18:23.759490 26577 raft_consensus.cc:399] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:23.759568 26577 raft_consensus.cc:493] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:23.759743 26577 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:23.760605 26577 raft_consensus.cc:515] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER }
I20260812 06:18:23.761073 26577 leader_election.cc:304] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [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: 63135ad8d50b4ae58b3c2559a00bdb9b; no voters: 
I20260812 06:18:23.761451 26577 leader_election.cc:290] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:23.761626 26580 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:23.761904 26580 raft_consensus.cc:697] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 1 LEADER]: Becoming Leader. State: Replica: 63135ad8d50b4ae58b3c2559a00bdb9b, State: Running, Role: LEADER
I20260812 06:18:23.762279 26580 consensus_queue.cc:237] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [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: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER }
I20260812 06:18:23.762547 26577 sys_catalog.cc:565] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:23.764384 26583 sys_catalog.cc:455] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 63135ad8d50b4ae58b3c2559a00bdb9b. Latest consensus state: current_term: 1 leader_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER } }
I20260812 06:18:23.764523 26583 sys_catalog.cc:458] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:23.764370 26581 sys_catalog.cc:455] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "63135ad8d50b4ae58b3c2559a00bdb9b" member_type: VOTER } }
I20260812 06:18:23.764819 26581 sys_catalog.cc:458] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:23.764896 26591 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:23.767505 26591 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:23.767805 26500 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:23.772531 26591 catalog_manager.cc:1383] Generated new cluster ID: 77eb91ee7b1041bba08e0cdd5a1bd660
I20260812 06:18:23.772620 26591 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:23.783396 26591 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:23.784327 26591 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:23.796357 26591 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: Generated new TSK 0
I20260812 06:18:23.797102 26591 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:23.800578 26500 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:23.803362 26607 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:23.803453 26604 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:23.803544 26603 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:23.803761 26500 server_base.cc:1061] running on GCE node
I20260812 06:18:23.803983 26500 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:23.804035 26500 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:23.804059 26500 hybrid_clock.cc:648] HybridClock initialized: now 1786515503804058 us; error 0 us; skew 500 ppm
I20260812 06:18:23.805099 26500 webserver.cc:533] Webserver started at http://127.25.225.1:37661/ using document root <none> and password file <none>
I20260812 06:18:23.805266 26500 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:23.805326 26500 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:23.805397 26500 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:23.805843 26500 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/instance:
uuid: "ca7bf93714e14c6a9571c4d2545777c3"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-mvvj"
I20260812 06:18:23.807857 26500 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:23.809044 26612 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:23.809304 26500 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:23.809367 26500 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root
uuid: "ca7bf93714e14c6a9571c4d2545777c3"
format_stamp: "Formatted at 2026-08-12 06:18:23 on dist-test-slave-mvvj"
I20260812 06:18:23.809512 26500 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-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:23.821533 26500 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:23.822088 26500 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:23.822618 26500 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:23.823526 26500 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:23.823581 26500 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.823654 26500 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:23.823694 26500 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:23.830204 26500 rpc_server.cc:307] RPC server started. Bound to: 127.25.225.1:35557
I20260812 06:18:23.830267 26686 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.225.1:35557 every 8 connection(s)
I20260812 06:18:23.844894 26687 heartbeater.cc:344] Connected to a master server at 127.25.225.62:35521
I20260812 06:18:23.845182 26687 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:23.845856 26687 heartbeater.cc:507] Master 127.25.225.62:35521 requested a full tablet report, sending...
I20260812 06:18:23.847476 26535 ts_manager.cc:194] Registered new tserver with Master: ca7bf93714e14c6a9571c4d2545777c3 (127.25.225.1:35557)
I20260812 06:18:23.847910 26500 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016971121s
I20260812 06:18:23.849318 26535 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44250
I20260812 06:18:23.858484 26535 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44266:
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:23.872852 26646 tablet_service.cc:1511] Processing CreateTablet for tablet b454fbad85714fa8a84280bbaf33d8d3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=66f3ef410fed4156aaced82d5ac4e3bc]), partition=
I20260812 06:18:23.873337 26646 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b454fbad85714fa8a84280bbaf33d8d3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:23.876114 26701 tablet_bootstrap.cc:492] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Bootstrap starting.
I20260812 06:18:23.876992 26701 tablet_bootstrap.cc:654] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:23.878123 26701 tablet_bootstrap.cc:492] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: No bootstrap required, opened a new log
I20260812 06:18:23.878254 26701 ts_tablet_manager.cc:1403] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:23.878707 26701 raft_consensus.cc:359] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca7bf93714e14c6a9571c4d2545777c3" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 35557 } }
I20260812 06:18:23.878831 26701 raft_consensus.cc:385] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:23.878903 26701 raft_consensus.cc:740] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ca7bf93714e14c6a9571c4d2545777c3, State: Initialized, Role: FOLLOWER
I20260812 06:18:23.879204 26701 consensus_queue.cc:260] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [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: "ca7bf93714e14c6a9571c4d2545777c3" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 35557 } }
I20260812 06:18:23.879522 26701 raft_consensus.cc:399] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:23.879602 26701 raft_consensus.cc:493] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:23.879649 26701 raft_consensus.cc:3060] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:23.880455 26701 raft_consensus.cc:515] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca7bf93714e14c6a9571c4d2545777c3" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 35557 } }
I20260812 06:18:23.880627 26701 leader_election.cc:304] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [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: ca7bf93714e14c6a9571c4d2545777c3; no voters: 
I20260812 06:18:23.880869 26701 leader_election.cc:290] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:23.880971 26703 raft_consensus.cc:2804] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:23.881270 26701 ts_tablet_manager.cc:1434] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:23.881245 26703 raft_consensus.cc:697] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 1 LEADER]: Becoming Leader. State: Replica: ca7bf93714e14c6a9571c4d2545777c3, State: Running, Role: LEADER
I20260812 06:18:23.881476 26687 heartbeater.cc:499] Master 127.25.225.62:35521 was elected leader, sending a full tablet report...
I20260812 06:18:23.881500 26703 consensus_queue.cc:237] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [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: "ca7bf93714e14c6a9571c4d2545777c3" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 35557 } }
I20260812 06:18:23.884768 26535 catalog_manager.cc:5719] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 reported cstate change: term changed from 0 to 1, leader changed from <none> to ca7bf93714e14c6a9571c4d2545777c3 (127.25.225.1). New cstate: current_term: 1 leader_uuid: "ca7bf93714e14c6a9571c4d2545777c3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca7bf93714e14c6a9571c4d2545777c3" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 35557 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:23.958050 26500 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.028s	sys 0.004s
I20260812 06:18:24.081692 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=15.086190
I20260812 06:18:24.257933 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.176s	user 0.123s	sys 0.048s Metrics: {"bytes_written":12307497,"cfile_init":1,"compiler_manager_pool.queue_time_us":1273,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":949,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42025,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":125,"threads_started":1,"update_count":1500}
I20260812 06:18:24.258993 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling LogGCOp(b454fbad85714fa8a84280bbaf33d8d3): free 8725963 bytes of WAL
I20260812 06:18:24.259292 26618 log_reader.cc:385] T b454fbad85714fa8a84280bbaf33d8d3: removed 1 log segments from log reader
I20260812 06:18:24.259366 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000001 (ops 1-6)
I20260812 06:18:24.261270 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: LogGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:24.261631 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3): 12308960 bytes on disk
I20260812 06:18:24.262153 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.262524 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:24.281962 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.282485 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:24.409821 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.127s	user 0.091s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631319,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":8277,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25552,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":300,"threads_started":5,"update_count":2000}
I20260812 06:18:24.410414 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:24.456714 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.046s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17876,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.457266 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:24.473310 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.474000 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:24.599123 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.125s	user 0.113s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":9237,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22615,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:24.599762 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:24.644678 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.045s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.645190 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:24.655666 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.656153 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:24.771993 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.116s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":7307,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22571,"lbm_writes_lt_1ms":443,"mutex_wait_us":115,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:24.772611 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:24.818673 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.046s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15535,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.819263 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:24.830168 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.830650 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:24.982012 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.151s	user 0.101s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":10162,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24023,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:24.982714 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:25.028780 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.046s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14210,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.029258 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:25.040681 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.041424 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:25.167680 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.126s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":758,"lbm_read_time_us":8657,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23903,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:25.168305 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:25.217955 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.049s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15994,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.218597 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:25.229637 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.230253 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:25.357371 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.127s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":8560,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26133,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.358031 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:25.398561 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.040s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17908,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.399091 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:25.412048 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.412500 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:25.441780 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.029s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1449,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1369,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:25.442669 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling LogGCOp(b454fbad85714fa8a84280bbaf33d8d3): free 124257180 bytes of WAL
I20260812 06:18:25.442911 26618 log_reader.cc:385] T b454fbad85714fa8a84280bbaf33d8d3: removed 12 log segments from log reader
I20260812 06:18:25.442957 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000002 (ops 7-11)
I20260812 06:18:25.442987 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000003 (ops 12-16)
I20260812 06:18:25.443050 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000004 (ops 17-20)
I20260812 06:18:25.443112 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000005 (ops 21-25)
I20260812 06:18:25.443153 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000006 (ops 26-30)
I20260812 06:18:25.443245 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000007 (ops 31-35)
I20260812 06:18:25.443280 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000008 (ops 36-40)
I20260812 06:18:25.443307 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000009 (ops 41-45)
I20260812 06:18:25.443368 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000010 (ops 46-50)
I20260812 06:18:25.443403 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000011 (ops 51-55)
I20260812 06:18:25.443444 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000012 (ops 56-60)
I20260812 06:18:25.443476 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000013 (ops 61-65)
I20260812 06:18:25.471982 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: LogGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:25.472855 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=4.173312
I20260812 06:18:25.490800 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.018s	user 0.010s	sys 0.006s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":7337,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:18:25.491276 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.196750
I20260812 06:18:25.500597 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2831,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:25.501081 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:25.678084 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.177s	user 0.126s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":466,"lbm_read_time_us":13085,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33878,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:25.678733 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3): 447 bytes on disk
I20260812 06:18:25.679239 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.679865 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=14.095187
I20260812 06:18:25.728029 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.048s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.728586 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:25.744326 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.744879 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:25.908921 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.164s	user 0.125s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":11937,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29201,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:18:25.909569 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=14.095187
I20260812 06:18:25.959036 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.049s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21188,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.959705 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.108035 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.148s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":304,"lbm_read_time_us":8773,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24378,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.108649 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=14.095187
I20260812 06:18:26.159044 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.050s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23245,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.159575 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:26.173784 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.174317 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.341562 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.167s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1111,"lbm_read_time_us":10661,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25699,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:18:26.342199 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=11.118625
I20260812 06:18:26.376796 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.034s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13682,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:26.377351 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:26.390377 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.390962 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.531472 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.140s	user 0.117s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":11071,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25545,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:26.532169 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=7.149875
I20260812 06:18:26.563027 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.031s	user 0.016s	sys 0.011s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12989,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:26.563609 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:26.580477 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5700,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.581199 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.703766 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.122s	user 0.091s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":611,"lbm_read_time_us":7699,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20350,"lbm_writes_lt_1ms":343,"mutex_wait_us":92,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":1500}
I20260812 06:18:26.704331 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=7.149875
I20260812 06:18:26.736415 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.032s	user 0.024s	sys 0.007s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":13615,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:26.736977 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:26.750278 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.750751 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.864565 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.114s	user 0.090s	sys 0.012s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528892,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":7439,"lbm_reads_lt_1ms":372,"lbm_write_time_us":18019,"lbm_writes_lt_1ms":343,"mutex_wait_us":63,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.865244 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=6.157687
I20260812 06:18:26.893770 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.028s	user 0.013s	sys 0.013s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12210,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:26.894335 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:26.921270 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.027s	user 0.020s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":144,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1759,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1858,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:26.922117 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling LogGCOp(b454fbad85714fa8a84280bbaf33d8d3): free 108535514 bytes of WAL
I20260812 06:18:26.922380 26618 log_reader.cc:385] T b454fbad85714fa8a84280bbaf33d8d3: removed 11 log segments from log reader
I20260812 06:18:26.922453 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000014 (ops 66-70)
I20260812 06:18:26.922508 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000015 (ops 71-75)
I20260812 06:18:26.922567 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000016 (ops 76-80)
I20260812 06:18:26.922608 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000017 (ops 81-85)
I20260812 06:18:26.922645 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000018 (ops 86-90)
I20260812 06:18:26.922684 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000019 (ops 91-94)
I20260812 06:18:26.922721 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000020 (ops 95-99)
I20260812 06:18:26.922760 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000021 (ops 100-104)
I20260812 06:18:26.922796 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000022 (ops 105-108)
I20260812 06:18:26.922832 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000023 (ops 109-113)
I20260812 06:18:26.922869 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000024 (ops 114-118)
I20260812 06:18:26.946625 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: LogGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:26.947158 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3): 447 bytes on disk
I20260812 06:18:26.947686 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.948256 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=3.181125
I20260812 06:18:26.967247 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.019s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7476,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:26.967793 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling LogGCOp(b454fbad85714fa8a84280bbaf33d8d3): free 11564875 bytes of WAL
I20260812 06:18:26.968071 26618 log_reader.cc:385] T b454fbad85714fa8a84280bbaf33d8d3: removed 1 log segments from log reader
I20260812 06:18:26.968142 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000025 (ops 119-122)
I20260812 06:18:26.970360 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: LogGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:26.970712 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:26.981334 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3586,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.981856 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:27.110649 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.129s	user 0.115s	sys 0.012s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631420,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":489,"lbm_read_time_us":11649,"lbm_reads_lt_1ms":473,"lbm_write_time_us":23074,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":118,"threads_started":1,"update_count":2000}
I20260812 06:18:27.111392 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:27.161478 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.050s	user 0.036s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19453,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.162055 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:27.177995 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.178676 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:27.329118 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.150s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":12189,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25066,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:18:27.329893 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:27.374331 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.044s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14789,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":1500}
I20260812 06:18:27.374819 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:27.386994 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.387804 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:27.522300 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.134s	user 0.097s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":7771,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25578,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:18:27.522979 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:27.560461 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.037s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14218,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.560977 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:27.674479 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.113s	user 0.085s	sys 0.023s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":274,"lbm_read_time_us":5956,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21307,"lbm_writes_lt_1ms":343,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.675176 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:27.713088 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.038s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15636,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.713742 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:27.822837 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.109s	user 0.081s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":251,"lbm_read_time_us":6989,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18148,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":1500}
I20260812 06:18:27.823655 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:27.870464 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.047s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17415,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.871014 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:27.882802 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.883278 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.007253 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.124s	user 0.099s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":7586,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23412,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:28.007889 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:28.054878 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.047s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":26146,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.055444 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:28.069017 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4857,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.069555 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.213140 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.143s	user 0.122s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":441,"lbm_read_time_us":9731,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29161,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2000}
I20260812 06:18:28.214020 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=10.126437
I20260812 06:18:28.257313 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.257915 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:28.275494 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.276221 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.318681 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushMRSOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.042s	user 0.030s	sys 0.006s Metrics: {"bytes_written":1152511,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1506,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1719,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:28.319414 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling LogGCOp(b454fbad85714fa8a84280bbaf33d8d3): free 108535655 bytes of WAL
I20260812 06:18:28.319664 26618 log_reader.cc:385] T b454fbad85714fa8a84280bbaf33d8d3: removed 11 log segments from log reader
I20260812 06:18:28.319712 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000026 (ops 123-127)
I20260812 06:18:28.319743 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000027 (ops 128-132)
I20260812 06:18:28.319815 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000028 (ops 133-136)
I20260812 06:18:28.319911 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000029 (ops 137-141)
I20260812 06:18:28.319979 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000030 (ops 142-146)
I20260812 06:18:28.320024 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000031 (ops 147-151)
I20260812 06:18:28.320070 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000032 (ops 152-156)
I20260812 06:18:28.320112 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000033 (ops 157-161)
I20260812 06:18:28.320155 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000034 (ops 162-166)
I20260812 06:18:28.320199 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000035 (ops 167-170)
I20260812 06:18:28.320240 26618 log.cc:1079] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/b454fbad85714fa8a84280bbaf33d8d3/wal-000000036 (ops 171-175)
I20260812 06:18:28.345674 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: LogGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:28.346194 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=3.181125
I20260812 06:18:28.370483 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.024s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7349,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:28.371016 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:28.381649 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.382190 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3): 447 bytes on disk
I20260812 06:18:28.382660 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: UndoDeltaBlockGCOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.383447 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.604118 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.220s	user 0.151s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836366,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":312,"lbm_read_time_us":15850,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36830,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24960,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:28.604936 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=14.095187
I20260812 06:18:28.654742 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.049s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19467,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:28.655468 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.820483 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.165s	user 0.109s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":410,"lbm_read_time_us":9891,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26413,"lbm_writes_lt_1ms":443,"mutex_wait_us":92,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.821136 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=14.095187
I20260812 06:18:28.879413 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.058s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24284,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.880110 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=2.188937
I20260812 06:18:28.892181 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.892843 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=1.000000
I20260812 06:18:28.982249 26500 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.024s	user 1.848s	sys 0.150s
I20260812 06:18:29.072011 26500 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.004s	sys 0.000s
I20260812 06:18:29.072270 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: MajorDeltaCompactionOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.179s	user 0.120s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1375,"dirs.run_cpu_time_us":677,"dirs.run_wall_time_us":3393,"lbm_read_time_us":10488,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28727,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:29.072867 26500 tablet_server.cc:179] TabletServer@127.25.225.1:0 shutting down...
I20260812 06:18:29.072985 26688 maintenance_manager.cc:419] P ca7bf93714e14c6a9571c4d2545777c3: Scheduling FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3): perf score=6.157687
I20260812 06:18:29.098217 26618 maintenance_manager.cc:643] P ca7bf93714e14c6a9571c4d2545777c3: FlushDeltaMemStoresOp(b454fbad85714fa8a84280bbaf33d8d3) complete. Timing: real 0.025s	user 0.010s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10484,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:29.099014 26500 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:29.099764 26500 tablet_replica.cc:333] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3: stopping tablet replica
I20260812 06:18:29.100054 26500 raft_consensus.cc:2243] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.100558 26500 raft_consensus.cc:2272] T b454fbad85714fa8a84280bbaf33d8d3 P ca7bf93714e14c6a9571c4d2545777c3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.118039 26500 tablet_server.cc:196] TabletServer@127.25.225.1:0 shutdown complete.
I20260812 06:18:29.123210 26500 master.cc:562] Master@127.25.225.62:35521 shutting down...
I20260812 06:18:29.128032 26500 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:29.128263 26500 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:29.128356 26500 tablet_replica.cc:333] T 00000000000000000000000000000000 P 63135ad8d50b4ae58b3c2559a00bdb9b: stopping tablet replica
I20260812 06:18:29.141026 26500 master.cc:584] Master@127.25.225.62:35521 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5544 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:29.250069 26500 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.225.62:42449
I20260812 06:18:29.250578 26500 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:29.253062 26721 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:29.253151 26500 server_base.cc:1061] running on GCE node
W20260812 06:18:29.253078 26722 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:29.253334 26725 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:29.253618 26500 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.253665 26500 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:29.253690 26500 hybrid_clock.cc:648] HybridClock initialized: now 1786515509253690 us; error 0 us; skew 500 ppm
I20260812 06:18:29.254740 26500 webserver.cc:533] Webserver started at http://127.25.225.62:38891/ using document root <none> and password file <none>
I20260812 06:18:29.254885 26500 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.254931 26500 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.254988 26500 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.255339 26500 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/master-0-root/instance:
uuid: "61aa4b685eb04ecea7f2556772533fbd"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-mvvj"
I20260812 06:18:29.257099 26500 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:29.258194 26732 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:29.258596 26500 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:29.258692 26500 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/master-0-root
uuid: "61aa4b685eb04ecea7f2556772533fbd"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-mvvj"
I20260812 06:18:29.258802 26500 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-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:29.274993 26500 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.275447 26500 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.279970 26500 rpc_server.cc:307] RPC server started. Bound to: 127.25.225.62:42449
I20260812 06:18:29.280879 26791 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.225.62:42449 every 8 connection(s)
I20260812 06:18:29.281404 26792 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:29.283152 26792 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd: Bootstrap starting.
I20260812 06:18:29.283962 26792 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.285039 26792 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd: No bootstrap required, opened a new log
I20260812 06:18:29.285434 26792 raft_consensus.cc:359] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER }
I20260812 06:18:29.285527 26792 raft_consensus.cc:385] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.285562 26792 raft_consensus.cc:740] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 61aa4b685eb04ecea7f2556772533fbd, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.285729 26792 consensus_queue.cc:260] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [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: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER }
I20260812 06:18:29.285830 26792 raft_consensus.cc:399] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.285856 26792 raft_consensus.cc:493] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.285889 26792 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.286597 26792 raft_consensus.cc:515] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER }
I20260812 06:18:29.286725 26792 leader_election.cc:304] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [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: 61aa4b685eb04ecea7f2556772533fbd; no voters: 
I20260812 06:18:29.286895 26792 leader_election.cc:290] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.287041 26795 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.287268 26795 raft_consensus.cc:697] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 1 LEADER]: Becoming Leader. State: Replica: 61aa4b685eb04ecea7f2556772533fbd, State: Running, Role: LEADER
I20260812 06:18:29.287457 26792 sys_catalog.cc:565] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:29.287472 26795 consensus_queue.cc:237] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [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: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER }
I20260812 06:18:29.288045 26796 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "61aa4b685eb04ecea7f2556772533fbd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER } }
I20260812 06:18:29.288082 26798 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 61aa4b685eb04ecea7f2556772533fbd. Latest consensus state: current_term: 1 leader_uuid: "61aa4b685eb04ecea7f2556772533fbd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61aa4b685eb04ecea7f2556772533fbd" member_type: VOTER } }
I20260812 06:18:29.288337 26798 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.288239 26796 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:29.288980 26808 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:29.289777 26808 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:29.290074 26500 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:29.291786 26808 catalog_manager.cc:1383] Generated new cluster ID: d72c55c1dfbd481f8925e28711877912
I20260812 06:18:29.291877 26808 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:29.299002 26808 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:29.299674 26808 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:29.305941 26808 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd: Generated new TSK 0
I20260812 06:18:29.306106 26808 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:29.322762 26500 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:29.325618 26500 server_base.cc:1061] running on GCE node
W20260812 06:18:29.325568 26816 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:29.325517 26817 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:29.325517 26819 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:29.325950 26500 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:29.326030 26500 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:29.326067 26500 hybrid_clock.cc:648] HybridClock initialized: now 1786515509326066 us; error 0 us; skew 500 ppm
I20260812 06:18:29.326999 26500 webserver.cc:533] Webserver started at http://127.25.225.1:34643/ using document root <none> and password file <none>
I20260812 06:18:29.327183 26500 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:29.327258 26500 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:29.327340 26500 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:29.327819 26500 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/instance:
uuid: "48806eb230de4f31856903e61925f06f"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-mvvj"
I20260812 06:18:29.329540 26500 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:29.330637 26825 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:29.330947 26500 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:29.331040 26500 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root
uuid: "48806eb230de4f31856903e61925f06f"
format_stamp: "Formatted at 2026-08-12 06:18:29 on dist-test-slave-mvvj"
I20260812 06:18:29.331138 26500 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-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:29.339676 26500 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:29.340174 26500 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:29.340546 26500 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:29.341073 26500 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:29.341141 26500 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.341214 26500 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:29.341274 26500 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:29.346359 26500 rpc_server.cc:307] RPC server started. Bound to: 127.25.225.1:37531
I20260812 06:18:29.349650 26902 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.225.1:37531 every 8 connection(s)
I20260812 06:18:29.361635 26903 heartbeater.cc:344] Connected to a master server at 127.25.225.62:42449
I20260812 06:18:29.361814 26903 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:29.362125 26903 heartbeater.cc:507] Master 127.25.225.62:42449 requested a full tablet report, sending...
I20260812 06:18:29.362922 26750 ts_manager.cc:194] Registered new tserver with Master: 48806eb230de4f31856903e61925f06f (127.25.225.1:37531)
I20260812 06:18:29.363413 26500 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015713128s
I20260812 06:18:29.363817 26750 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39050
I20260812 06:18:29.371974 26750 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39054:
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:29.382182 26859 tablet_service.cc:1511] Processing CreateTablet for tablet 454f5d2959074db0adf5efc8b01baecd (DEFAULT_TABLE table=heavy-update-compaction-test [id=840fa831f36c4724b977f0c243b01709]), partition=
I20260812 06:18:29.382520 26859 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 454f5d2959074db0adf5efc8b01baecd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:29.384896 26915 tablet_bootstrap.cc:492] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Bootstrap starting.
I20260812 06:18:29.385896 26915 tablet_bootstrap.cc:654] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:29.387190 26915 tablet_bootstrap.cc:492] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: No bootstrap required, opened a new log
I20260812 06:18:29.387375 26915 ts_tablet_manager.cc:1403] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:29.387974 26915 raft_consensus.cc:359] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48806eb230de4f31856903e61925f06f" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 37531 } }
I20260812 06:18:29.388109 26915 raft_consensus.cc:385] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:29.388163 26915 raft_consensus.cc:740] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 48806eb230de4f31856903e61925f06f, State: Initialized, Role: FOLLOWER
I20260812 06:18:29.388326 26915 consensus_queue.cc:260] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [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: "48806eb230de4f31856903e61925f06f" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 37531 } }
I20260812 06:18:29.388427 26915 raft_consensus.cc:399] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:29.388454 26915 raft_consensus.cc:493] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:29.388526 26915 raft_consensus.cc:3060] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:29.389412 26915 raft_consensus.cc:515] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48806eb230de4f31856903e61925f06f" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 37531 } }
I20260812 06:18:29.389597 26915 leader_election.cc:304] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [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: 48806eb230de4f31856903e61925f06f; no voters: 
I20260812 06:18:29.389873 26915 leader_election.cc:290] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:29.390064 26917 raft_consensus.cc:2804] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:29.390230 26915 ts_tablet_manager.cc:1434] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:29.390250 26903 heartbeater.cc:499] Master 127.25.225.62:42449 was elected leader, sending a full tablet report...
I20260812 06:18:29.390317 26917 raft_consensus.cc:697] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 1 LEADER]: Becoming Leader. State: Replica: 48806eb230de4f31856903e61925f06f, State: Running, Role: LEADER
I20260812 06:18:29.390488 26917 consensus_queue.cc:237] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [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: "48806eb230de4f31856903e61925f06f" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 37531 } }
I20260812 06:18:29.392040 26749 catalog_manager.cc:5719] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f reported cstate change: term changed from 0 to 1, leader changed from <none> to 48806eb230de4f31856903e61925f06f (127.25.225.1). New cstate: current_term: 1 leader_uuid: "48806eb230de4f31856903e61925f06f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48806eb230de4f31856903e61925f06f" member_type: VOTER last_known_addr { host: "127.25.225.1" port: 37531 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:29.453207 26500 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.011s	sys 0.013s
I20260812 06:18:29.600165 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushMRSOp(454f5d2959074db0adf5efc8b01baecd): perf score=19.054940
I20260812 06:18:29.755662 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushMRSOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.155s	user 0.121s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":820,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39005,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:29.756392 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling LogGCOp(454f5d2959074db0adf5efc8b01baecd): free 20743880 bytes of WAL
I20260812 06:18:29.756642 26831 log_reader.cc:385] T 454f5d2959074db0adf5efc8b01baecd: removed 2 log segments from log reader
I20260812 06:18:29.756716 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000001 (ops 1-6)
I20260812 06:18:29.756771 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000002 (ops 7-11)
I20260812 06:18:29.760900 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: LogGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:29.761291 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd): 16411392 bytes on disk
I20260812 06:18:29.761739 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.762126 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:29.779361 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.779899 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:29.958580 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.179s	user 0.109s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1289,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26615,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"thread_start_us":427,"threads_started":5,"update_count":2000}
I20260812 06:18:29.959335 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:30.008785 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.049s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20783,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.009346 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:30.020769 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.009s	sys 0.001s 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:30.021361 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:30.204181 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.183s	user 0.135s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":10377,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35267,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":49920,"update_count":2500}
I20260812 06:18:30.205034 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:30.255532 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.050s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21966,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.256234 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:30.272349 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.272899 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:30.430533 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.157s	user 0.120s	sys 0.033s 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":147,"lbm_read_time_us":10372,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29737,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:30.431259 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:30.480988 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.050s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18600,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.481549 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:30.493227 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.493992 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:30.662211 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.168s	user 0.126s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":463,"lbm_read_time_us":9251,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32352,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":2500}
I20260812 06:18:30.662976 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:30.721662 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.058s	user 0.036s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.722179 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:30.733330 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.734172 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:30.923421 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.189s	user 0.115s	sys 0.069s 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":440,"lbm_read_time_us":13216,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30002,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2500}
I20260812 06:18:30.924069 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:30.969646 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.045s	user 0.021s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19422,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.970383 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushMRSOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:30.998117 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushMRSOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1419,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1481,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:30.998775 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling LogGCOp(454f5d2959074db0adf5efc8b01baecd): free 115943176 bytes of WAL
I20260812 06:18:30.999058 26831 log_reader.cc:385] T 454f5d2959074db0adf5efc8b01baecd: removed 11 log segments from log reader
I20260812 06:18:30.999128 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000003 (ops 12-16)
I20260812 06:18:30.999168 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000004 (ops 17-21)
I20260812 06:18:30.999199 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000005 (ops 22-26)
I20260812 06:18:30.999235 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000006 (ops 27-31)
I20260812 06:18:30.999269 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000007 (ops 32-36)
I20260812 06:18:30.999310 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000008 (ops 37-41)
I20260812 06:18:30.999341 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000009 (ops 42-46)
I20260812 06:18:30.999362 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000010 (ops 47-51)
I20260812 06:18:30.999397 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000011 (ops 52-56)
I20260812 06:18:30.999429 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000012 (ops 57-61)
I20260812 06:18:30.999462 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000013 (ops 62-66)
I20260812 06:18:31.027498 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: LogGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:31.027973 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd): 462 bytes on disk
I20260812 06:18:31.028703 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.029268 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=3.181125
I20260812 06:18:31.042109 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4723,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:31.042689 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:31.056710 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5088,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.057296 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:31.251288 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.194s	user 0.128s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2321,"lbm_read_time_us":13531,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31313,"lbm_writes_lt_1ms":643,"mutex_wait_us":601,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:31.252219 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:31.299285 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.047s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19369,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:31.299896 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:31.315235 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.316046 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:31.503181 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.187s	user 0.111s	sys 0.074s 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":308,"lbm_read_time_us":12691,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31496,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:18:31.503821 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:31.575372 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.071s	user 0.029s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23377,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.576134 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:31.587203 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.587908 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:31.764063 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.176s	user 0.112s	sys 0.061s 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":362,"lbm_read_time_us":13365,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28082,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:18:31.764953 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=11.118625
I20260812 06:18:31.809495 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.044s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16117,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.810304 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:31.833184 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.023s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.833719 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:31.843712 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3695,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.844431 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:32.036959 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.192s	user 0.125s	sys 0.059s 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":203,"lbm_read_time_us":12722,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32766,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:18:32.037738 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:32.102541 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.065s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21377,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.103163 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:32.114302 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.114777 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:32.292975 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.178s	user 0.090s	sys 0.088s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":750,"lbm_read_time_us":12328,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29754,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:32.293694 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=10.126437
I20260812 06:18:32.333297 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16770,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.333863 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:32.344877 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.345419 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:32.480466 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.135s	user 0.119s	sys 0.015s 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":181,"lbm_read_time_us":10755,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24818,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:32.481317 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=10.126437
I20260812 06:18:32.535550 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.054s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18201,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.536149 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:32.551999 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.552784 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushMRSOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:32.588718 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushMRSOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.036s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1727,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2276,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:32.589385 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling LogGCOp(454f5d2959074db0adf5efc8b01baecd): free 124710298 bytes of WAL
I20260812 06:18:32.589690 26831 log_reader.cc:385] T 454f5d2959074db0adf5efc8b01baecd: removed 12 log segments from log reader
I20260812 06:18:32.589736 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000014 (ops 67-71)
I20260812 06:18:32.589864 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000015 (ops 72-76)
I20260812 06:18:32.589895 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000016 (ops 77-81)
I20260812 06:18:32.589913 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000017 (ops 82-86)
I20260812 06:18:32.589949 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000018 (ops 87-91)
I20260812 06:18:32.589995 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000019 (ops 92-96)
I20260812 06:18:32.590029 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000020 (ops 97-101)
I20260812 06:18:32.590068 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000021 (ops 102-106)
I20260812 06:18:32.590096 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000022 (ops 107-111)
I20260812 06:18:32.590134 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000023 (ops 112-116)
I20260812 06:18:32.590174 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000024 (ops 117-121)
I20260812 06:18:32.590214 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000025 (ops 122-126)
I20260812 06:18:32.617493 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: LogGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:32.617949 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=3.181125
I20260812 06:18:32.638581 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7502,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:32.639154 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd): 463 bytes on disk
I20260812 06:18:32.639600 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.640136 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:32.654874 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.655663 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:32.848351 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.192s	user 0.114s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1029,"lbm_read_time_us":11830,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39625,"lbm_writes_lt_1ms":643,"mutex_wait_us":77,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:32.849144 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:32.900679 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.051s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.901226 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:32.918303 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.918882 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:33.092026 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.173s	user 0.143s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":9560,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34509,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":361,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":112768,"update_count":2500}
I20260812 06:18:33.092789 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:33.153067 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.060s	user 0.047s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25340,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.153759 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:33.171288 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.171928 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:33.332195 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.160s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":413,"lbm_read_time_us":12247,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29573,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":104448,"update_count":2500}
I20260812 06:18:33.333102 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:33.385435 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.052s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.386001 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:33.397498 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.398183 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:33.556849 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.158s	user 0.120s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1423,"lbm_read_time_us":10028,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31147,"lbm_writes_lt_1ms":543,"mutex_wait_us":522,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:33.557550 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=11.118625
I20260812 06:18:33.596714 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":13415135,"delete_count":0,"lbm_write_time_us":16687,"lbm_writes_lt_1ms":330,"reinsert_count":0,"update_count":1635}
I20260812 06:18:33.597332 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.196750
I20260812 06:18:33.621285 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.024s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":76,"mutex_wait_us":24,"reinsert_count":0,"update_count":365}
I20260812 06:18:33.621845 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:33.636575 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5634,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.637180 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:33.818073 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.181s	user 0.131s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774773,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1014,"lbm_read_time_us":12307,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29495,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:33.818856 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=14.095187
I20260812 06:18:33.877108 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.058s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26680,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.877720 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:33.894493 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.017s	user 0.001s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.895258 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:34.084086 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.189s	user 0.138s	sys 0.048s 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":383,"lbm_read_time_us":13750,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30754,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:18:34.084743 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=15.087375
I20260812 06:18:34.139395 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.054s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":19782,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:34.140213 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:34.166878 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5481,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.167470 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=2.188937
I20260812 06:18:34.178042 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.178576 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushMRSOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:34.224254 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushMRSOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.045s	user 0.045s	sys 0.000s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1518,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1995,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:18:34.225368 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling LogGCOp(454f5d2959074db0adf5efc8b01baecd): free 129320774 bytes of WAL
I20260812 06:18:34.225718 26831 log_reader.cc:385] T 454f5d2959074db0adf5efc8b01baecd: removed 13 log segments from log reader
I20260812 06:18:34.225786 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000026 (ops 127-131)
I20260812 06:18:34.225847 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000027 (ops 132-136)
I20260812 06:18:34.225905 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000028 (ops 137-141)
I20260812 06:18:34.225952 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000029 (ops 142-146)
I20260812 06:18:34.225998 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000030 (ops 147-150)
I20260812 06:18:34.226039 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000031 (ops 151-155)
I20260812 06:18:34.226087 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000032 (ops 156-160)
I20260812 06:18:34.226133 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000033 (ops 161-165)
I20260812 06:18:34.226181 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000034 (ops 166-170)
I20260812 06:18:34.226222 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000035 (ops 171-175)
I20260812 06:18:34.226269 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000036 (ops 176-180)
I20260812 06:18:34.226317 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000037 (ops 181-184)
I20260812 06:18:34.226366 26831 log.cc:1079] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: Deleting log segment in path: /tmp/dist-test-taskelyOfV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515503679288-26500-0/minicluster-data/ts-0-root/wals/454f5d2959074db0adf5efc8b01baecd/wal-000000038 (ops 185-189)
I20260812 06:18:34.260317 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: LogGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:18:34.260775 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd): 507 bytes on disk
I20260812 06:18:34.261329 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: UndoDeltaBlockGCOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.262019 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=4.173312
I20260812 06:18:34.278473 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":6519,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:34.278981 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.196750
I20260812 06:18:34.288986 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: FlushDeltaMemStoresOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":2958,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:18:34.289656 26904 maintenance_manager.cc:419] P 48806eb230de4f31856903e61925f06f: Scheduling MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd): perf score=1.000000
I20260812 06:18:34.406855 26500 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.953s	user 1.847s	sys 0.163s
I20260812 06:18:34.513888 26500 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.001s	sys 0.000s
I20260812 06:18:34.514456 26500 tablet_server.cc:179] TabletServer@127.25.225.1:0 shutting down...
I20260812 06:18:34.526916 26831 maintenance_manager.cc:643] P 48806eb230de4f31856903e61925f06f: MajorDeltaCompactionOp(454f5d2959074db0adf5efc8b01baecd) complete. Timing: real 0.237s	user 0.165s	sys 0.072s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082227,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":533,"lbm_read_time_us":15747,"lbm_reads_lt_1ms":863,"lbm_write_time_us":42038,"lbm_writes_lt_1ms":843,"mutex_wait_us":42,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":74,"threads_started":1,"update_count":4000}
I20260812 06:18:34.527614 26500 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:34.528055 26500 tablet_replica.cc:333] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f: stopping tablet replica
I20260812 06:18:34.528225 26500 raft_consensus.cc:2243] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.528407 26500 raft_consensus.cc:2272] T 454f5d2959074db0adf5efc8b01baecd P 48806eb230de4f31856903e61925f06f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.533807 26500 tablet_server.cc:196] TabletServer@127.25.225.1:0 shutdown complete.
I20260812 06:18:34.600387 26500 master.cc:562] Master@127.25.225.62:42449 shutting down...
I20260812 06:18:34.604086 26500 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.604305 26500 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.604383 26500 tablet_replica.cc:333] T 00000000000000000000000000000000 P 61aa4b685eb04ecea7f2556772533fbd: stopping tablet replica
I20260812 06:18:34.617085 26500 master.cc:584] Master@127.25.225.62:42449 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5467 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11013 ms total)

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