[==========] 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:19:34.337004 25600 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.0.62:35225
I20260812 06:19:34.338191 25600 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:19:34.338882 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.346999 25610 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:19:34.347060 25600 server_base.cc:1061] running on GCE node
W20260812 06:19:34.347311 25609 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:19:34.346961 25613 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:19:34.348084 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.348279 25600 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:19:34.348359 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515574348355 us; error 0 us; skew 500 ppm
I20260812 06:19:34.350739 25600 webserver.cc:533] Webserver started at http://127.25.0.62:39475/ using document root <none> and password file <none>
I20260812 06:19:34.351426 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.351529 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.351809 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.353700 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/master-0-root/instance:
uuid: "66ae1f0a5e3045beb7ba2689deac20f1"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-1nl6"
I20260812 06:19:34.358206 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:19:34.361162 25619 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:19:34.363134 25600 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:19:34.363363 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/master-0-root
uuid: "66ae1f0a5e3045beb7ba2689deac20f1"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-1nl6"
I20260812 06:19:34.363539 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-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:19:34.384243 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.385282 25600 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:19:34.385540 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.397300 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.62:35225
I20260812 06:19:34.397347 25694 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.62:35225 every 8 connection(s)
I20260812 06:19:34.400434 25695 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:19:34.408059 25695 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: Bootstrap starting.
I20260812 06:19:34.411435 25695 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.412814 25695 log.cc:826] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:34.415714 25695 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: No bootstrap required, opened a new log
I20260812 06:19:34.419294 25695 raft_consensus.cc:359] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER }
I20260812 06:19:34.419551 25695 raft_consensus.cc:385] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.419647 25695 raft_consensus.cc:740] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 66ae1f0a5e3045beb7ba2689deac20f1, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.420456 25695 consensus_queue.cc:260] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [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: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER }
I20260812 06:19:34.420647 25695 raft_consensus.cc:399] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.420696 25695 raft_consensus.cc:493] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.420910 25695 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.421985 25695 raft_consensus.cc:515] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER }
I20260812 06:19:34.422551 25695 leader_election.cc:304] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [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: 66ae1f0a5e3045beb7ba2689deac20f1; no voters: 
I20260812 06:19:34.422991 25695 leader_election.cc:290] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.423177 25700 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.423465 25700 raft_consensus.cc:697] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 1 LEADER]: Becoming Leader. State: Replica: 66ae1f0a5e3045beb7ba2689deac20f1, State: Running, Role: LEADER
I20260812 06:19:34.424001 25700 consensus_queue.cc:237] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [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: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER }
I20260812 06:19:34.424576 25695 sys_catalog.cc:565] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:34.426224 25704 sys_catalog.cc:455] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 66ae1f0a5e3045beb7ba2689deac20f1. Latest consensus state: current_term: 1 leader_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER } }
I20260812 06:19:34.426244 25702 sys_catalog.cc:455] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "66ae1f0a5e3045beb7ba2689deac20f1" member_type: VOTER } }
I20260812 06:19:34.426394 25704 sys_catalog.cc:458] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.426393 25702 sys_catalog.cc:458] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.426867 25718 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:34.429826 25718 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:34.430299 25600 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:34.436589 25718 catalog_manager.cc:1383] Generated new cluster ID: c3f97b58e8074e8385603b5707d2b3f2
I20260812 06:19:34.436746 25718 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:34.445889 25718 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:34.447172 25718 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:34.469475 25718 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: Generated new TSK 0
I20260812 06:19:34.470443 25718 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:34.496124 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.499847 25738 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:19:34.500094 25600 server_base.cc:1061] running on GCE node
W20260812 06:19:34.499950 25746 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:19:34.499888 25744 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:19:34.500681 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.500752 25600 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:19:34.500772 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515574500772 us; error 0 us; skew 500 ppm
I20260812 06:19:34.502103 25600 webserver.cc:533] Webserver started at http://127.25.0.1:46239/ using document root <none> and password file <none>
I20260812 06:19:34.502378 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.502446 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.502578 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.503196 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/instance:
uuid: "a0209449384942cb9cefb319ee91b0d3"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-1nl6"
I20260812 06:19:34.505170 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:34.506651 25756 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:19:34.507158 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:34.507292 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root
uuid: "a0209449384942cb9cefb319ee91b0d3"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-1nl6"
I20260812 06:19:34.507416 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-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:19:34.523015 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.523561 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.524147 25600 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:34.525168 25600 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:34.525226 25600 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.525306 25600 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:34.525348 25600 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.533314 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.1:35751
I20260812 06:19:34.533388 25849 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.1:35751 every 8 connection(s)
I20260812 06:19:34.545593 25850 heartbeater.cc:344] Connected to a master server at 127.25.0.62:35225
I20260812 06:19:34.545926 25850 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:34.546459 25850 heartbeater.cc:507] Master 127.25.0.62:35225 requested a full tablet report, sending...
I20260812 06:19:34.548122 25647 ts_manager.cc:194] Registered new tserver with Master: a0209449384942cb9cefb319ee91b0d3 (127.25.0.1:35751)
I20260812 06:19:34.548409 25600 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014354856s
I20260812 06:19:34.549485 25647 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57054
I20260812 06:19:34.560760 25647 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57060:
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:19:34.581974 25799 tablet_service.cc:1511] Processing CreateTablet for tablet 9148ebe5708c4838bf1a91ead83b0222 (DEFAULT_TABLE table=heavy-update-compaction-test [id=38c240334bec46fdb25a54bfeee85717]), partition=
I20260812 06:19:34.582649 25799 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9148ebe5708c4838bf1a91ead83b0222. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:34.586216 25867 tablet_bootstrap.cc:492] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Bootstrap starting.
I20260812 06:19:34.587863 25867 tablet_bootstrap.cc:654] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.589977 25867 tablet_bootstrap.cc:492] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: No bootstrap required, opened a new log
I20260812 06:19:34.590137 25867 ts_tablet_manager.cc:1403] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:34.590828 25867 raft_consensus.cc:359] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0209449384942cb9cefb319ee91b0d3" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35751 } }
I20260812 06:19:34.591029 25867 raft_consensus.cc:385] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.591076 25867 raft_consensus.cc:740] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a0209449384942cb9cefb319ee91b0d3, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.591284 25867 consensus_queue.cc:260] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [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: "a0209449384942cb9cefb319ee91b0d3" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35751 } }
I20260812 06:19:34.591403 25867 raft_consensus.cc:399] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.591456 25867 raft_consensus.cc:493] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.591511 25867 raft_consensus.cc:3060] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.592764 25867 raft_consensus.cc:515] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0209449384942cb9cefb319ee91b0d3" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35751 } }
I20260812 06:19:34.592952 25867 leader_election.cc:304] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [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: a0209449384942cb9cefb319ee91b0d3; no voters: 
I20260812 06:19:34.593235 25867 leader_election.cc:290] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.593458 25871 raft_consensus.cc:2804] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.593771 25867 ts_tablet_manager.cc:1434] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:19:34.593770 25871 raft_consensus.cc:697] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 1 LEADER]: Becoming Leader. State: Replica: a0209449384942cb9cefb319ee91b0d3, State: Running, Role: LEADER
I20260812 06:19:34.594280 25850 heartbeater.cc:499] Master 127.25.0.62:35225 was elected leader, sending a full tablet report...
I20260812 06:19:34.594070 25871 consensus_queue.cc:237] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [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: "a0209449384942cb9cefb319ee91b0d3" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35751 } }
I20260812 06:19:34.597828 25647 catalog_manager.cc:5719] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 reported cstate change: term changed from 0 to 1, leader changed from <none> to a0209449384942cb9cefb319ee91b0d3 (127.25.0.1). New cstate: current_term: 1 leader_uuid: "a0209449384942cb9cefb319ee91b0d3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0209449384942cb9cefb319ee91b0d3" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 35751 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:34.674994 25600 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.069s	user 0.017s	sys 0.011s
I20260812 06:19:34.784678 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222): perf score=11.117440
I20260812 06:19:34.949208 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.164s	user 0.130s	sys 0.032s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":341,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1017,"drs_written":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37433,"lbm_writes_lt_1ms":467,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":3328,"thread_start_us":218,"threads_started":1,"update_count":1000}
I20260812 06:19:34.950743 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling LogGCOp(9148ebe5708c4838bf1a91ead83b0222): free 8725963 bytes of WAL
I20260812 06:19:34.951159 25761 log_reader.cc:385] T 9148ebe5708c4838bf1a91ead83b0222: removed 1 log segments from log reader
I20260812 06:19:34.951275 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000001 (ops 1-6)
I20260812 06:19:34.954648 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: LogGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:34.955430 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222): 8616791 bytes on disk
I20260812 06:19:34.956388 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.957042 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:34.975998 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.019s	user 0.004s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7198,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.976749 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:35.121568 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.145s	user 0.098s	sys 0.034s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16118646,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1845,"lbm_read_time_us":9714,"lbm_reads_lt_1ms":350,"lbm_write_time_us":22145,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":827,"threads_started":5,"update_count":1450}
I20260812 06:19:35.122880 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:35.188751 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.066s	user 0.022s	sys 0.029s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":26337,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.189421 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:35.206800 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.207660 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:35.375254 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.167s	user 0.135s	sys 0.032s 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":621,"lbm_read_time_us":13257,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31907,"lbm_writes_lt_1ms":443,"mutex_wait_us":230,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":2000}
I20260812 06:19:35.376551 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:35.428416 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.051s	user 0.015s	sys 0.034s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20360,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.428987 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:35.456434 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.027s	user 0.010s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7398,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.457000 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:35.656054 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.199s	user 0.138s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":557,"lbm_read_time_us":13614,"lbm_reads_lt_1ms":464,"lbm_write_time_us":32506,"lbm_writes_lt_1ms":443,"mutex_wait_us":509,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:35.657162 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:35.715544 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.058s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.716090 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:35.844498 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.128s	user 0.112s	sys 0.015s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":659,"lbm_read_time_us":8683,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25310,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:19:35.845137 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:35.891299 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19779,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.891871 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:35.907874 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.908656 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:36.072067 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.163s	user 0.136s	sys 0.024s 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":888,"lbm_read_time_us":11193,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30928,"lbm_writes_lt_1ms":443,"mutex_wait_us":389,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:36.072660 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:36.136369 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.063s	user 0.021s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17119,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.137313 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:36.153707 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.154255 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:36.335577 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.181s	user 0.108s	sys 0.071s 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":444,"lbm_read_time_us":13811,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29414,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:19:36.336691 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:36.403808 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.067s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18840,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.404560 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:36.418272 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.419046 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:36.561235 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.142s	user 0.120s	sys 0.020s 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":2475,"lbm_read_time_us":10541,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26184,"lbm_writes_lt_1ms":443,"mutex_wait_us":649,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29696,"update_count":2000}
I20260812 06:19:36.562278 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=10.126437
I20260812 06:19:36.611492 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.049s	user 0.037s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21709,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.612103 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:36.624711 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.625784 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:36.659984 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.034s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":2024,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1727,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:36.661276 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling LogGCOp(9148ebe5708c4838bf1a91ead83b0222): free 124257180 bytes of WAL
I20260812 06:19:36.661685 25761 log_reader.cc:385] T 9148ebe5708c4838bf1a91ead83b0222: removed 12 log segments from log reader
I20260812 06:19:36.661759 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000002 (ops 7-11)
I20260812 06:19:36.661808 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000003 (ops 12-16)
I20260812 06:19:36.661839 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000004 (ops 17-21)
I20260812 06:19:36.661876 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000005 (ops 22-26)
I20260812 06:19:36.661901 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000006 (ops 27-30)
I20260812 06:19:36.661932 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000007 (ops 31-35)
I20260812 06:19:36.661955 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000008 (ops 36-40)
I20260812 06:19:36.661979 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000009 (ops 41-45)
I20260812 06:19:36.662016 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000010 (ops 46-50)
I20260812 06:19:36.662045 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000011 (ops 51-55)
I20260812 06:19:36.662068 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000012 (ops 56-60)
I20260812 06:19:36.662091 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000013 (ops 61-65)
I20260812 06:19:36.699803 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: LogGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.038s	user 0.000s	sys 0.037s Metrics: {}
I20260812 06:19:36.700342 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:36.732300 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.031s	user 0.012s	sys 0.006s Metrics: {"bytes_written":4225732,"delete_count":0,"lbm_write_time_us":7689,"lbm_writes_lt_1ms":106,"mutex_wait_us":305,"reinsert_count":0,"update_count":515}
I20260812 06:19:36.732872 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:36.749697 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":6499,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:36.750629 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222): 473 bytes on disk
I20260812 06:19:36.751452 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.752373 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:36.972867 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.220s	user 0.151s	sys 0.058s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836372,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":696,"lbm_read_time_us":17396,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41947,"lbm_writes_lt_1ms":643,"mutex_wait_us":82,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":98,"threads_started":1,"update_count":3000}
I20260812 06:19:36.973910 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:37.034634 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.060s	user 0.040s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24683,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.035374 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:37.049418 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.014s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.050300 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:37.255698 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.205s	user 0.166s	sys 0.020s 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":392,"lbm_read_time_us":12048,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41289,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:37.256687 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:37.312536 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.056s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24268,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.313449 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:37.482782 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.169s	user 0.139s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":977,"lbm_read_time_us":12475,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29977,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:19:37.483569 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=11.118625
I20260812 06:19:37.538431 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.055s	user 0.020s	sys 0.031s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19271,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:37.539355 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:37.560539 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.021s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6510,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.561174 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:37.742151 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.181s	user 0.139s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2119,"lbm_read_time_us":11164,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30440,"lbm_writes_lt_1ms":443,"mutex_wait_us":1011,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:19:37.743319 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=11.118625
I20260812 06:19:37.789664 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19617,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:37.790311 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:37.817551 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.027s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.818198 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:37.831329 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4988,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.832118 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:37.999900 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.168s	user 0.123s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1048,"lbm_read_time_us":12705,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33633,"lbm_writes_lt_1ms":543,"mutex_wait_us":127,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2500}
I20260812 06:19:38.000610 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=11.118625
I20260812 06:19:38.053615 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.053s	user 0.030s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22032,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:38.054697 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:38.087024 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.032s	user 0.002s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6333,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.087612 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:38.099589 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.100570 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:38.291949 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.191s	user 0.146s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":319,"lbm_read_time_us":12031,"lbm_reads_lt_1ms":573,"lbm_write_time_us":37171,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":774656,"update_count":2500}
I20260812 06:19:38.292745 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:38.363807 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.071s	user 0.027s	sys 0.039s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":33446,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.364601 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:38.379109 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.014s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.379783 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:38.414731 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":318,"dirs.run_wall_time_us":1538,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1755,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:38.415642 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling LogGCOp(9148ebe5708c4838bf1a91ead83b0222): free 129320564 bytes of WAL
I20260812 06:19:38.415917 25761 log_reader.cc:385] T 9148ebe5708c4838bf1a91ead83b0222: removed 13 log segments from log reader
I20260812 06:19:38.415983 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000014 (ops 66-70)
I20260812 06:19:38.416044 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000015 (ops 71-75)
I20260812 06:19:38.416105 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000016 (ops 76-80)
I20260812 06:19:38.416149 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000017 (ops 81-84)
I20260812 06:19:38.416188 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000018 (ops 85-89)
I20260812 06:19:38.416227 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000019 (ops 90-94)
I20260812 06:19:38.416268 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000020 (ops 95-99)
I20260812 06:19:38.416306 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000021 (ops 100-104)
I20260812 06:19:38.416347 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000022 (ops 105-109)
I20260812 06:19:38.416548 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000023 (ops 110-114)
I20260812 06:19:38.416599 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000024 (ops 115-118)
I20260812 06:19:38.416640 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000025 (ops 119-123)
I20260812 06:19:38.416680 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000026 (ops 124-128)
I20260812 06:19:38.453907 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: LogGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.038s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:19:38.454668 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=4.173312
I20260812 06:19:38.476047 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.021s	user 0.011s	sys 0.008s Metrics: {"bytes_written":5743635,"delete_count":0,"lbm_write_time_us":8810,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:19:38.477807 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222): 472 bytes on disk
I20260812 06:19:38.478539 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.479358 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.196750
I20260812 06:19:38.491791 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:19:38.492453 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:38.779404 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.287s	user 0.180s	sys 0.089s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938753,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":375,"lbm_read_time_us":20116,"lbm_reads_lt_1ms":766,"lbm_write_time_us":44717,"lbm_writes_lt_1ms":743,"mutex_wait_us":91,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":132,"threads_started":1,"update_count":3500}
I20260812 06:19:38.781016 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=18.063937
I20260812 06:19:38.859277 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.078s	user 0.034s	sys 0.043s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31606,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:38.859947 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:38.877519 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.878309 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:39.131160 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.253s	user 0.173s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4905,"lbm_read_time_us":16614,"lbm_reads_lt_1ms":664,"lbm_write_time_us":44260,"lbm_writes_lt_1ms":643,"mutex_wait_us":369,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":3000}
I20260812 06:19:39.132563 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=15.087375
I20260812 06:19:39.218887 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.086s	user 0.023s	sys 0.041s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":30976,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:19:39.219795 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=6.157687
I20260812 06:19:39.253058 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.033s	user 0.021s	sys 0.005s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":12133,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:39.253563 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:39.498510 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.245s	user 0.166s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836136,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":539,"lbm_read_time_us":17705,"lbm_reads_lt_1ms":664,"lbm_write_time_us":41356,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3000}
I20260812 06:19:39.499403 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=18.063937
I20260812 06:19:39.583613 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.084s	user 0.058s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":33836,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:39.584491 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:39.598505 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.599211 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:39.842794 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.243s	user 0.170s	sys 0.073s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2084,"lbm_read_time_us":16210,"lbm_reads_lt_1ms":672,"lbm_write_time_us":43431,"lbm_writes_lt_1ms":643,"mutex_wait_us":808,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:19:39.843838 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:39.910969 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.067s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26345,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.911599 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:39.923655 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.924252 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:40.134744 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.210s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":772,"lbm_read_time_us":16639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35717,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:19:40.135540 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=14.095187
I20260812 06:19:40.213161 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.077s	user 0.037s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.213905 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:40.227661 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.228216 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:40.268713 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushMRSOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.040s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1535,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:40.269665 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling LogGCOp(9148ebe5708c4838bf1a91ead83b0222): free 124257508 bytes of WAL
I20260812 06:19:40.269932 25761 log_reader.cc:385] T 9148ebe5708c4838bf1a91ead83b0222: removed 12 log segments from log reader
I20260812 06:19:40.269979 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000027 (ops 129-132)
I20260812 06:19:40.270010 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000028 (ops 133-137)
I20260812 06:19:40.270072 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000029 (ops 138-142)
I20260812 06:19:40.270107 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000030 (ops 143-147)
I20260812 06:19:40.270156 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000031 (ops 148-152)
I20260812 06:19:40.270210 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000032 (ops 153-157)
I20260812 06:19:40.270254 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000033 (ops 158-162)
I20260812 06:19:40.270298 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000034 (ops 163-167)
I20260812 06:19:40.270339 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000035 (ops 168-172)
I20260812 06:19:40.270380 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000036 (ops 173-177)
I20260812 06:19:40.270423 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000037 (ops 178-182)
I20260812 06:19:40.270465 25761 log.cc:1079] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/9148ebe5708c4838bf1a91ead83b0222/wal-000000038 (ops 183-187)
I20260812 06:19:40.299154 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: LogGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:40.299686 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222): 473 bytes on disk
I20260812 06:19:40.300175 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: UndoDeltaBlockGCOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.300783 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:40.320560 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.020s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.321205 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:40.333886 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5161,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.334740 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:40.586114 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.251s	user 0.162s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938786,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":463,"lbm_read_time_us":20131,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44892,"lbm_writes_lt_1ms":743,"mutex_wait_us":36,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":30464,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:40.587172 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=15.087375
I20260812 06:19:40.603753 25600 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.928s	user 2.096s	sys 0.160s
I20260812 06:19:40.634582 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.047s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22431,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:40.635542 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222): perf score=2.188937
I20260812 06:19:40.648797 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: FlushDeltaMemStoresOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.649456 25851 maintenance_manager.cc:419] P a0209449384942cb9cefb319ee91b0d3: Scheduling MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222): perf score=1.000000
I20260812 06:19:40.662977 25600 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.058s	user 0.006s	sys 0.000s
I20260812 06:19:40.663951 25600 tablet_server.cc:179] TabletServer@127.25.0.1:0 shutting down...
I20260812 06:19:40.789316 25761 maintenance_manager.cc:643] P a0209449384942cb9cefb319ee91b0d3: MajorDeltaCompactionOp(9148ebe5708c4838bf1a91ead83b0222) complete. Timing: real 0.140s	user 0.113s	sys 0.024s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512287,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":10385,"lbm_reads_lt_1ms":518,"lbm_write_time_us":29291,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:19:40.790148 25600 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:40.790576 25600 tablet_replica.cc:333] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3: stopping tablet replica
I20260812 06:19:40.790833 25600 raft_consensus.cc:2243] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:40.791118 25600 raft_consensus.cc:2272] T 9148ebe5708c4838bf1a91ead83b0222 P a0209449384942cb9cefb319ee91b0d3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:40.802665 25600 tablet_server.cc:196] TabletServer@127.25.0.1:0 shutdown complete.
I20260812 06:19:40.838231 25600 master.cc:562] Master@127.25.0.62:35225 shutting down...
I20260812 06:19:40.842653 25600 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:40.842866 25600 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:40.842991 25600 tablet_replica.cc:333] T 00000000000000000000000000000000 P 66ae1f0a5e3045beb7ba2689deac20f1: stopping tablet replica
I20260812 06:19:40.856398 25600 master.cc:584] Master@127.25.0.62:35225 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6626 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:40.979396 25600 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.0.62:40375
I20260812 06:19:40.979840 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:40.982766 25600 server_base.cc:1061] running on GCE node
W20260812 06:19:40.982792 25909 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:19:40.983129 25905 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:19:40.982813 25903 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:19:40.983702 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:40.983804 25600 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:19:40.983824 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515580983823 us; error 0 us; skew 500 ppm
I20260812 06:19:40.984911 25600 webserver.cc:533] Webserver started at http://127.25.0.62:44271/ using document root <none> and password file <none>
I20260812 06:19:40.985131 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:40.985205 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:40.985301 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:40.985826 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/master-0-root/instance:
uuid: "60fea23e54e74dbe94618935a2865198"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-1nl6"
I20260812 06:19:40.987716 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.002s
I20260812 06:19:40.989142 25916 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:19:40.989498 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:40.989714 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/master-0-root
uuid: "60fea23e54e74dbe94618935a2865198"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-1nl6"
I20260812 06:19:40.989828 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-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:19:41.004058 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.004575 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.009630 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.62:40375
I20260812 06:19:41.011313 26018 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:19:41.013254 26016 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.62:40375 every 8 connection(s)
I20260812 06:19:41.014808 26018 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198: Bootstrap starting.
I20260812 06:19:41.015785 26018 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.017549 26018 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198: No bootstrap required, opened a new log
I20260812 06:19:41.018075 26018 raft_consensus.cc:359] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "60fea23e54e74dbe94618935a2865198" member_type: VOTER }
I20260812 06:19:41.018210 26018 raft_consensus.cc:385] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.018270 26018 raft_consensus.cc:740] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 60fea23e54e74dbe94618935a2865198, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.018483 26018 consensus_queue.cc:260] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [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: "60fea23e54e74dbe94618935a2865198" member_type: VOTER }
I20260812 06:19:41.018601 26018 raft_consensus.cc:399] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.018652 26018 raft_consensus.cc:493] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.018713 26018 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.019678 26018 raft_consensus.cc:515] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "60fea23e54e74dbe94618935a2865198" member_type: VOTER }
I20260812 06:19:41.019865 26018 leader_election.cc:304] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [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: 60fea23e54e74dbe94618935a2865198; no voters: 
I20260812 06:19:41.020130 26018 leader_election.cc:290] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.020365 26024 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.020651 26024 raft_consensus.cc:697] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 1 LEADER]: Becoming Leader. State: Replica: 60fea23e54e74dbe94618935a2865198, State: Running, Role: LEADER
I20260812 06:19:41.020707 26018 sys_catalog.cc:565] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.020819 26024 consensus_queue.cc:237] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [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: "60fea23e54e74dbe94618935a2865198" member_type: VOTER }
I20260812 06:19:41.021315 26027 sys_catalog.cc:455] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 60fea23e54e74dbe94618935a2865198. Latest consensus state: current_term: 1 leader_uuid: "60fea23e54e74dbe94618935a2865198" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "60fea23e54e74dbe94618935a2865198" member_type: VOTER } }
I20260812 06:19:41.021301 26025 sys_catalog.cc:455] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "60fea23e54e74dbe94618935a2865198" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "60fea23e54e74dbe94618935a2865198" member_type: VOTER } }
I20260812 06:19:41.021477 26027 sys_catalog.cc:458] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.021543 26025 sys_catalog.cc:458] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.021914 26036 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.022780 26036 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.022975 25600 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.024920 26036 catalog_manager.cc:1383] Generated new cluster ID: 3a13b3bddd5342549b05fe8e9703ac31
I20260812 06:19:41.025002 26036 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.073870 26036 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.074612 26036 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.083467 26036 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198: Generated new TSK 0
I20260812 06:19:41.083770 26036 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.088481 25600 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.091069 26051 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:19:41.091104 26050 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:19:41.091308 26055 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:19:41.091328 25600 server_base.cc:1061] running on GCE node
I20260812 06:19:41.091681 25600 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.091732 25600 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:19:41.091794 25600 hybrid_clock.cc:648] HybridClock initialized: now 1786515581091793 us; error 0 us; skew 500 ppm
I20260812 06:19:41.092885 25600 webserver.cc:533] Webserver started at http://127.25.0.1:46165/ using document root <none> and password file <none>
I20260812 06:19:41.093206 25600 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.093286 25600 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.093379 25600 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.093840 25600 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/instance:
uuid: "6ca250a0cf094a02877956e04a8fc1c7"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-1nl6"
I20260812 06:19:41.095947 25600 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:41.097573 26063 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:19:41.098081 25600 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:41.098307 25600 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root
uuid: "6ca250a0cf094a02877956e04a8fc1c7"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-1nl6"
I20260812 06:19:41.098475 25600 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-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:19:41.108999 25600 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.109714 25600 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.110114 25600 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:41.110675 25600 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:41.110746 25600 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.110814 25600 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:41.110869 25600 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.120388 25600 rpc_server.cc:307] RPC server started. Bound to: 127.25.0.1:33139
I20260812 06:19:41.121057 26171 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.0.1:33139 every 8 connection(s)
I20260812 06:19:41.133507 26173 heartbeater.cc:344] Connected to a master server at 127.25.0.62:40375
I20260812 06:19:41.133658 26173 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:41.133978 26173 heartbeater.cc:507] Master 127.25.0.62:40375 requested a full tablet report, sending...
I20260812 06:19:41.134804 25949 ts_manager.cc:194] Registered new tserver with Master: 6ca250a0cf094a02877956e04a8fc1c7 (127.25.0.1:33139)
I20260812 06:19:41.135368 25600 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013914099s
I20260812 06:19:41.135701 25949 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36028
I20260812 06:19:41.145567 25949 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36032:
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:19:41.157066 26112 tablet_service.cc:1511] Processing CreateTablet for tablet 1154eed6ec6a49748f07b295c2443c24 (DEFAULT_TABLE table=heavy-update-compaction-test [id=41eeda92588f419aa1b3b54dffa1e27e]), partition=
I20260812 06:19:41.157471 26112 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1154eed6ec6a49748f07b295c2443c24. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.160496 26193 tablet_bootstrap.cc:492] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Bootstrap starting.
I20260812 06:19:41.161662 26193 tablet_bootstrap.cc:654] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.163623 26193 tablet_bootstrap.cc:492] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: No bootstrap required, opened a new log
I20260812 06:19:41.163817 26193 ts_tablet_manager.cc:1403] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:41.164435 26193 raft_consensus.cc:359] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ca250a0cf094a02877956e04a8fc1c7" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 33139 } }
I20260812 06:19:41.164553 26193 raft_consensus.cc:385] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.164578 26193 raft_consensus.cc:740] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6ca250a0cf094a02877956e04a8fc1c7, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.164752 26193 consensus_queue.cc:260] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [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: "6ca250a0cf094a02877956e04a8fc1c7" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 33139 } }
I20260812 06:19:41.164832 26193 raft_consensus.cc:399] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.164897 26193 raft_consensus.cc:493] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.164963 26193 raft_consensus.cc:3060] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.166198 26193 raft_consensus.cc:515] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ca250a0cf094a02877956e04a8fc1c7" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 33139 } }
I20260812 06:19:41.166355 26193 leader_election.cc:304] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [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: 6ca250a0cf094a02877956e04a8fc1c7; no voters: 
I20260812 06:19:41.166652 26193 leader_election.cc:290] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.167091 26197 raft_consensus.cc:2804] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.167181 26173 heartbeater.cc:499] Master 127.25.0.62:40375 was elected leader, sending a full tablet report...
I20260812 06:19:41.167219 26193 ts_tablet_manager.cc:1434] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:41.167603 26197 raft_consensus.cc:697] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 1 LEADER]: Becoming Leader. State: Replica: 6ca250a0cf094a02877956e04a8fc1c7, State: Running, Role: LEADER
I20260812 06:19:41.167800 26197 consensus_queue.cc:237] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [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: "6ca250a0cf094a02877956e04a8fc1c7" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 33139 } }
I20260812 06:19:41.169795 25949 catalog_manager.cc:5719] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6ca250a0cf094a02877956e04a8fc1c7 (127.25.0.1). New cstate: current_term: 1 leader_uuid: "6ca250a0cf094a02877956e04a8fc1c7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6ca250a0cf094a02877956e04a8fc1c7" member_type: VOTER last_known_addr { host: "127.25.0.1" port: 33139 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:41.242529 25600 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.067s	user 0.018s	sys 0.008s
I20260812 06:19:41.372042 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushMRSOp(1154eed6ec6a49748f07b295c2443c24): perf score=15.086190
I20260812 06:19:41.517789 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushMRSOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.145s	user 0.105s	sys 0.028s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":169,"dirs.run_cpu_time_us":330,"dirs.run_wall_time_us":1168,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33604,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1000}
I20260812 06:19:41.518741 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling LogGCOp(1154eed6ec6a49748f07b295c2443c24): free 20290830 bytes of WAL
I20260812 06:19:41.519043 26073 log_reader.cc:385] T 1154eed6ec6a49748f07b295c2443c24: removed 2 log segments from log reader
I20260812 06:19:41.519100 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000001 (ops 1-6)
I20260812 06:19:41.519140 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000002 (ops 7-10)
I20260812 06:19:41.524971 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: LogGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:41.525904 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:41.550238 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.024s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.550833 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24): 12308958 bytes on disk
I20260812 06:19:41.551398 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.552021 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:41.703197 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.151s	user 0.097s	sys 0.053s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":605,"lbm_read_time_us":10864,"lbm_reads_lt_1ms":360,"lbm_write_time_us":27985,"lbm_writes_lt_1ms":343,"mutex_wait_us":29,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17408,"thread_start_us":402,"threads_started":5,"update_count":1500}
I20260812 06:19:41.703912 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:41.743657 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.040s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.744525 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:41.760057 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.760584 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:41.913704 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.153s	user 0.109s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":587,"lbm_read_time_us":11640,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26910,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":122112,"update_count":2000}
I20260812 06:19:41.914821 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:41.955392 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.040s	user 0.031s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17486,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.956008 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:42.113632 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.157s	user 0.116s	sys 0.039s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":870,"lbm_read_time_us":11427,"lbm_reads_lt_1ms":367,"lbm_write_time_us":25319,"lbm_writes_lt_1ms":343,"mutex_wait_us":76,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:19:42.114553 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:42.168599 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.053s	user 0.016s	sys 0.029s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21607,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.169328 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:42.301697 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.132s	user 0.087s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1236,"lbm_read_time_us":8198,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24925,"lbm_writes_lt_1ms":343,"mutex_wait_us":290,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":50432,"update_count":1500}
I20260812 06:19:42.302639 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:42.354068 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.051s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19590,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.355079 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:42.368815 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.369656 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:42.517992 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.148s	user 0.123s	sys 0.023s 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":426,"lbm_read_time_us":12485,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30119,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:42.518734 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:42.581772 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.063s	user 0.036s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18114,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.582417 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:42.597535 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.598127 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:42.771063 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.173s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":12691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28343,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2000}
I20260812 06:19:42.771611 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:42.815817 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.044s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15652,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.816511 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:42.833634 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.834295 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:42.986694 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.152s	user 0.124s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1319,"lbm_read_time_us":11340,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27841,"lbm_writes_lt_1ms":443,"mutex_wait_us":558,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":55296,"update_count":2000}
I20260812 06:19:42.987803 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=10.126437
I20260812 06:19:43.034816 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.047s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22307,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.035528 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:43.048570 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.049203 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushMRSOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:43.086202 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushMRSOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.037s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":116,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":1848,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2411,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:43.087419 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling LogGCOp(1154eed6ec6a49748f07b295c2443c24): free 108988505 bytes of WAL
I20260812 06:19:43.087777 26073 log_reader.cc:385] T 1154eed6ec6a49748f07b295c2443c24: removed 11 log segments from log reader
I20260812 06:19:43.087831 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000003 (ops 11-15)
I20260812 06:19:43.087867 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000004 (ops 16-20)
I20260812 06:19:43.087932 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000005 (ops 21-25)
I20260812 06:19:43.087980 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000006 (ops 26-30)
I20260812 06:19:43.088030 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000007 (ops 31-35)
I20260812 06:19:43.088069 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000008 (ops 36-40)
I20260812 06:19:43.088114 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000009 (ops 41-45)
I20260812 06:19:43.088169 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000010 (ops 46-50)
I20260812 06:19:43.088222 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000011 (ops 51-54)
I20260812 06:19:43.088277 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000012 (ops 55-59)
I20260812 06:19:43.088320 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000013 (ops 60-64)
I20260812 06:19:43.117965 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: LogGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:43.118492 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24): 463 bytes on disk
I20260812 06:19:43.119062 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.119657 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:43.136956 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.137580 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:43.155350 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.018s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.156111 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:43.366607 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.210s	user 0.149s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":430,"lbm_read_time_us":16283,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39938,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23424,"thread_start_us":119,"threads_started":1,"update_count":3000}
I20260812 06:19:43.367347 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:43.422863 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.055s	user 0.020s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.423517 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:43.436852 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.437472 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:43.626289 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.189s	user 0.128s	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":820,"lbm_read_time_us":12682,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33931,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":42240,"update_count":2500}
I20260812 06:19:43.627218 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:43.704552 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.077s	user 0.044s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28732,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.705220 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:43.718322 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.719070 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:43.909965 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.191s	user 0.120s	sys 0.066s 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":1048,"lbm_read_time_us":14051,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32467,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2500}
I20260812 06:19:43.910755 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:43.981606 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.071s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25731,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.982304 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.001103 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.019s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.001674 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:44.212666 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.211s	user 0.175s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":16346,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33558,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:44.213550 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:44.277899 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.063s	user 0.037s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21302,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.278956 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.293015 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.293660 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:44.508922 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.215s	user 0.139s	sys 0.072s 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":837,"lbm_read_time_us":17494,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34122,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34688,"update_count":2500}
I20260812 06:19:44.509604 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:44.581492 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.072s	user 0.028s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22036,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.582172 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.594219 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.594769 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:44.806241 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.211s	user 0.134s	sys 0.076s 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":2327,"lbm_read_time_us":17677,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35683,"lbm_writes_lt_1ms":543,"mutex_wait_us":669,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:44.807263 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=11.118625
I20260812 06:19:44.862283 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.055s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":21537,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.863152 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.876149 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.877168 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.889609 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4728,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.890381 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushMRSOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:44.937254 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushMRSOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.047s	user 0.042s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1859,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2165,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:44.938452 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling LogGCOp(1154eed6ec6a49748f07b295c2443c24): free 136728229 bytes of WAL
I20260812 06:19:44.938954 26073 log_reader.cc:385] T 1154eed6ec6a49748f07b295c2443c24: removed 13 log segments from log reader
I20260812 06:19:44.939059 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000014 (ops 65-69)
I20260812 06:19:44.939126 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000015 (ops 70-74)
I20260812 06:19:44.939188 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000016 (ops 75-79)
I20260812 06:19:44.939230 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000017 (ops 80-84)
I20260812 06:19:44.939267 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000018 (ops 85-89)
I20260812 06:19:44.939308 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000019 (ops 90-94)
I20260812 06:19:44.939349 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000020 (ops 95-99)
I20260812 06:19:44.939399 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000021 (ops 100-104)
I20260812 06:19:44.939436 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000022 (ops 105-109)
I20260812 06:19:44.939476 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000023 (ops 110-114)
I20260812 06:19:44.939518 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000024 (ops 115-119)
I20260812 06:19:44.939559 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000025 (ops 120-124)
I20260812 06:19:44.939600 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000026 (ops 125-129)
I20260812 06:19:44.974893 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: LogGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.036s	user 0.005s	sys 0.027s Metrics: {}
I20260812 06:19:44.975390 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:44.991324 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5160,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.992079 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24): 493 bytes on disk
I20260812 06:19:44.992594 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.993153 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:45.005970 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.006800 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:45.282629 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.276s	user 0.192s	sys 0.078s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938898,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1264,"lbm_read_time_us":18519,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43904,"lbm_writes_lt_1ms":743,"mutex_wait_us":433,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":133,"threads_started":1,"update_count":3500}
I20260812 06:19:45.284122 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=18.063937
I20260812 06:19:45.370221 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.086s	user 0.031s	sys 0.043s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":36766,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.370987 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:45.383450 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.384025 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:45.635100 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.251s	user 0.153s	sys 0.088s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836140,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3805,"dirs.run_cpu_time_us":2514,"dirs.run_wall_time_us":24447,"lbm_read_time_us":17675,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39431,"lbm_writes_lt_1ms":643,"mutex_wait_us":587,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":35200,"update_count":3000}
I20260812 06:19:45.635834 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:45.705173 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.069s	user 0.054s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.706328 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:45.721791 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.722486 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:45.927323 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.205s	user 0.128s	sys 0.076s 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":2381,"lbm_read_time_us":16785,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33833,"lbm_writes_lt_1ms":543,"mutex_wait_us":587,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":42368,"update_count":2500}
I20260812 06:19:45.928349 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:45.988775 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.060s	user 0.034s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26378,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.989650 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:46.004733 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.005402 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:46.237510 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.232s	user 0.157s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1064,"lbm_read_time_us":16732,"lbm_reads_lt_1ms":572,"lbm_write_time_us":41624,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.238209 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:46.322249 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.084s	user 0.047s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":31501,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.323348 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:46.336977 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.337532 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:46.565516 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.228s	user 0.142s	sys 0.072s 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":1344,"lbm_read_time_us":16866,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35677,"lbm_writes_lt_1ms":543,"mutex_wait_us":591,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:46.566394 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=14.095187
I20260812 06:19:46.628599 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.062s	user 0.032s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26865,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.632125 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:46.652967 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.653578 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushMRSOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:46.687414 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushMRSOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":368,"dirs.run_wall_time_us":1768,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2357,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:46.688253 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling LogGCOp(1154eed6ec6a49748f07b295c2443c24): free 120100582 bytes of WAL
I20260812 06:19:46.688506 26073 log_reader.cc:385] T 1154eed6ec6a49748f07b295c2443c24: removed 12 log segments from log reader
I20260812 06:19:46.688552 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000027 (ops 130-134)
I20260812 06:19:46.688583 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000028 (ops 135-139)
I20260812 06:19:46.688649 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000029 (ops 140-144)
I20260812 06:19:46.688694 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000030 (ops 145-149)
I20260812 06:19:46.688741 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000031 (ops 150-154)
I20260812 06:19:46.688782 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000032 (ops 155-158)
I20260812 06:19:46.688844 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000033 (ops 159-163)
I20260812 06:19:46.688886 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000034 (ops 164-168)
I20260812 06:19:46.688928 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000035 (ops 169-172)
I20260812 06:19:46.688969 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000036 (ops 173-177)
I20260812 06:19:46.689010 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000037 (ops 178-182)
I20260812 06:19:46.689051 26073 log.cc:1079] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: Deleting log segment in path: /tmp/dist-test-taskDgIp_e/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574325223-25600-0/minicluster-data/ts-0-root/wals/1154eed6ec6a49748f07b295c2443c24/wal-000000038 (ops 183-186)
I20260812 06:19:46.719802 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: LogGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:46.721617 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=3.181125
I20260812 06:19:46.741458 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":5904,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:46.742206 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24): 462 bytes on disk
I20260812 06:19:46.742743 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: UndoDeltaBlockGCOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.743372 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:46.756965 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:46.757558 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:47.064349 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.307s	user 0.170s	sys 0.135s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1038,"lbm_read_time_us":23850,"lbm_reads_lt_1ms":774,"lbm_write_time_us":51607,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":27392,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:19:47.065100 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=16.079562
I20260812 06:19:47.144167 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.079s	user 0.044s	sys 0.028s Metrics: {"bytes_written":18255988,"delete_count":0,"lbm_write_time_us":32481,"lbm_writes_lt_1ms":448,"reinsert_count":0,"update_count":2225}
I20260812 06:19:47.145938 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.196750
I20260812 06:19:47.171330 25600 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.929s	user 2.034s	sys 0.287s
I20260812 06:19:47.172928 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":2912938,"delete_count":0,"lbm_write_time_us":6795,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:19:47.173636 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24): perf score=2.188937
I20260812 06:19:47.190404 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: FlushDeltaMemStoresOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":6478,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:19:47.191071 26174 maintenance_manager.cc:419] P 6ca250a0cf094a02877956e04a8fc1c7: Scheduling MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24): perf score=1.000000
I20260812 06:19:47.314666 25600 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.143s	user 0.003s	sys 0.000s
I20260812 06:19:47.315452 25600 tablet_server.cc:179] TabletServer@127.25.0.1:0 shutting down...
I20260812 06:19:47.477190 26073 maintenance_manager.cc:643] P 6ca250a0cf094a02877956e04a8fc1c7: MajorDeltaCompactionOp(1154eed6ec6a49748f07b295c2443c24) complete. Timing: real 0.286s	user 0.217s	sys 0.068s Metrics: {"cfile_cache_hit":183,"cfile_cache_hit_bytes":7429979,"cfile_cache_miss":450,"cfile_cache_miss_bytes":21406237,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1235,"lbm_read_time_us":19250,"lbm_reads_lt_1ms":482,"lbm_write_time_us":56772,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":151680,"update_count":3000}
I20260812 06:19:47.479787 25600 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.482846 25600 tablet_replica.cc:333] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7: stopping tablet replica
I20260812 06:19:47.484661 25600 raft_consensus.cc:2243] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.485266 25600 raft_consensus.cc:2272] T 1154eed6ec6a49748f07b295c2443c24 P 6ca250a0cf094a02877956e04a8fc1c7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.503528 25600 tablet_server.cc:196] TabletServer@127.25.0.1:0 shutdown complete.
I20260812 06:19:47.531493 25600 master.cc:562] Master@127.25.0.62:40375 shutting down...
I20260812 06:19:47.536441 25600 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.536967 25600 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.537168 25600 tablet_replica.cc:333] T 00000000000000000000000000000000 P 60fea23e54e74dbe94618935a2865198: stopping tablet replica
I20260812 06:19:47.551304 25600 master.cc:584] Master@127.25.0.62:40375 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6694 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13322 ms total)

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