[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:33.983431 17997 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.147.126:40933
I20260812 06:18:33.984640 17997 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:33.985373 17997 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.992933 18010 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.992908 18007 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:33.992908 17997 server_base.cc:1061] running on GCE node
W20260812 06:18:33.993219 18008 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:33.993848 17997 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.993973 17997 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:33.994031 17997 hybrid_clock.cc:648] HybridClock initialized: now 1786515513994027 us; error 0 us; skew 500 ppm
I20260812 06:18:33.996074 17997 webserver.cc:533] Webserver started at http://127.17.147.126:42035/ using document root <none> and password file <none>
I20260812 06:18:33.996728 17997 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.996814 17997 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.997133 17997 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.999138 17997 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/master-0-root/instance:
uuid: "71756be5e8154a71811097603778281e"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-nfb5"
I20260812 06:18:34.003288 17997 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.001s
I20260812 06:18:34.005795 18018 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.007050 17997 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:34.007186 17997 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/master-0-root
uuid: "71756be5e8154a71811097603778281e"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-nfb5"
I20260812 06:18:34.007302 17997 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:34.021986 17997 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.022861 17997 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:34.023099 17997 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.032132 17997 rpc_server.cc:307] RPC server started. Bound to: 127.17.147.126:40933
I20260812 06:18:34.032155 18101 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.147.126:40933 every 8 connection(s)
I20260812 06:18:34.034968 18103 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:34.041325 18103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: Bootstrap starting.
I20260812 06:18:34.044152 18103 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.045209 18103 log.cc:826] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:34.047247 18103 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: No bootstrap required, opened a new log
I20260812 06:18:34.050366 18103 raft_consensus.cc:359] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71756be5e8154a71811097603778281e" member_type: VOTER }
I20260812 06:18:34.050552 18103 raft_consensus.cc:385] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.050668 18103 raft_consensus.cc:740] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 71756be5e8154a71811097603778281e, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.051446 18103 consensus_queue.cc:260] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [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: "71756be5e8154a71811097603778281e" member_type: VOTER }
I20260812 06:18:34.051638 18103 raft_consensus.cc:399] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.051729 18103 raft_consensus.cc:493] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.051893 18103 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.052757 18103 raft_consensus.cc:515] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71756be5e8154a71811097603778281e" member_type: VOTER }
I20260812 06:18:34.053277 18103 leader_election.cc:304] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [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: 71756be5e8154a71811097603778281e; no voters: 
I20260812 06:18:34.053629 18103 leader_election.cc:290] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.053876 18107 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.054147 18107 raft_consensus.cc:697] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 1 LEADER]: Becoming Leader. State: Replica: 71756be5e8154a71811097603778281e, State: Running, Role: LEADER
I20260812 06:18:34.054620 18107 consensus_queue.cc:237] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [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: "71756be5e8154a71811097603778281e" member_type: VOTER }
I20260812 06:18:34.054877 18103 sys_catalog.cc:565] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:34.056841 18110 sys_catalog.cc:455] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 71756be5e8154a71811097603778281e. Latest consensus state: current_term: 1 leader_uuid: "71756be5e8154a71811097603778281e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71756be5e8154a71811097603778281e" member_type: VOTER } }
I20260812 06:18:34.056989 18110 sys_catalog.cc:458] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.057358 18122 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:34.057343 18109 sys_catalog.cc:455] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "71756be5e8154a71811097603778281e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "71756be5e8154a71811097603778281e" member_type: VOTER } }
I20260812 06:18:34.057452 18109 sys_catalog.cc:458] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:34.058153 17997 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:34.060148 18122 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:34.065229 18122 catalog_manager.cc:1383] Generated new cluster ID: f7e7c6db81b64ef9b20886dd9b056bab
I20260812 06:18:34.065299 18122 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:34.100374 18122 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:34.101859 18122 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:34.115429 18122 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: Generated new TSK 0
I20260812 06:18:34.116428 18122 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:34.123399 17997 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:34.127045 18131 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:34.127167 17997 server_base.cc:1061] running on GCE node
W20260812 06:18:34.127045 18130 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:34.127065 18134 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:34.127513 17997 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:34.127578 17997 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:34.127602 17997 hybrid_clock.cc:648] HybridClock initialized: now 1786515514127602 us; error 0 us; skew 500 ppm
I20260812 06:18:34.128628 17997 webserver.cc:533] Webserver started at http://127.17.147.65:43665/ using document root <none> and password file <none>
I20260812 06:18:34.128818 17997 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:34.128881 17997 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:34.128978 17997 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:34.129472 17997 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/instance:
uuid: "25f0112a75c8465bb37460d99a5cf91a"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-nfb5"
I20260812 06:18:34.131467 17997 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:34.132611 18144 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.132936 17997 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:34.133023 17997 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root
uuid: "25f0112a75c8465bb37460d99a5cf91a"
format_stamp: "Formatted at 2026-08-12 06:18:34 on dist-test-slave-nfb5"
I20260812 06:18:34.133112 17997 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:34.158278 17997 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:34.158864 17997 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:34.159471 17997 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:34.160535 17997 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:34.160594 17997 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.160674 17997 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:34.160722 17997 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:34.168390 17997 rpc_server.cc:307] RPC server started. Bound to: 127.17.147.65:33139
I20260812 06:18:34.168442 18253 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.147.65:33139 every 8 connection(s)
I20260812 06:18:34.179617 18254 heartbeater.cc:344] Connected to a master server at 127.17.147.126:40933
I20260812 06:18:34.179898 18254 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:34.180403 18254 heartbeater.cc:507] Master 127.17.147.126:40933 requested a full tablet report, sending...
I20260812 06:18:34.181968 18048 ts_manager.cc:194] Registered new tserver with Master: 25f0112a75c8465bb37460d99a5cf91a (127.17.147.65:33139)
I20260812 06:18:34.182606 17997 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013445859s
I20260812 06:18:34.183378 18048 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47332
I20260812 06:18:34.194482 18048 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47342:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:34.210570 18193 tablet_service.cc:1511] Processing CreateTablet for tablet 340bbfee30af49f3baf400d2973a1515 (DEFAULT_TABLE table=heavy-update-compaction-test [id=e0a263a3b1514ac891c53ec9c807583f]), partition=
I20260812 06:18:34.211217 18193 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 340bbfee30af49f3baf400d2973a1515. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:34.214118 18278 tablet_bootstrap.cc:492] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Bootstrap starting.
I20260812 06:18:34.215489 18278 tablet_bootstrap.cc:654] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:34.216780 18278 tablet_bootstrap.cc:492] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: No bootstrap required, opened a new log
I20260812 06:18:34.216902 18278 ts_tablet_manager.cc:1403] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:34.217617 18278 raft_consensus.cc:359] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25f0112a75c8465bb37460d99a5cf91a" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 33139 } }
I20260812 06:18:34.217823 18278 raft_consensus.cc:385] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:34.217881 18278 raft_consensus.cc:740] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 25f0112a75c8465bb37460d99a5cf91a, State: Initialized, Role: FOLLOWER
I20260812 06:18:34.218036 18278 consensus_queue.cc:260] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [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: "25f0112a75c8465bb37460d99a5cf91a" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 33139 } }
I20260812 06:18:34.218149 18278 raft_consensus.cc:399] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:34.218199 18278 raft_consensus.cc:493] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:34.218254 18278 raft_consensus.cc:3060] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:34.219195 18278 raft_consensus.cc:515] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25f0112a75c8465bb37460d99a5cf91a" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 33139 } }
I20260812 06:18:34.219367 18278 leader_election.cc:304] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [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: 25f0112a75c8465bb37460d99a5cf91a; no voters: 
I20260812 06:18:34.219602 18278 leader_election.cc:290] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:34.219734 18280 raft_consensus.cc:2804] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:34.219993 18278 ts_tablet_manager.cc:1434] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:34.220082 18280 raft_consensus.cc:697] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 1 LEADER]: Becoming Leader. State: Replica: 25f0112a75c8465bb37460d99a5cf91a, State: Running, Role: LEADER
I20260812 06:18:34.220280 18254 heartbeater.cc:499] Master 127.17.147.126:40933 was elected leader, sending a full tablet report...
I20260812 06:18:34.220309 18280 consensus_queue.cc:237] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [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: "25f0112a75c8465bb37460d99a5cf91a" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 33139 } }
I20260812 06:18:34.223973 18048 catalog_manager.cc:5719] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a reported cstate change: term changed from 0 to 1, leader changed from <none> to 25f0112a75c8465bb37460d99a5cf91a (127.17.147.65). New cstate: current_term: 1 leader_uuid: "25f0112a75c8465bb37460d99a5cf91a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25f0112a75c8465bb37460d99a5cf91a" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 33139 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:34.292007 17997 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.019s	sys 0.007s
I20260812 06:18:34.419705 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushMRSOp(340bbfee30af49f3baf400d2973a1515): perf score=15.086190
I20260812 06:18:34.602348 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushMRSOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.182s	user 0.137s	sys 0.036s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":327,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":313,"dirs.run_wall_time_us":816,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44509,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":213,"threads_started":1,"update_count":1500}
I20260812 06:18:34.603821 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling LogGCOp(340bbfee30af49f3baf400d2973a1515): free 8725963 bytes of WAL
I20260812 06:18:34.604228 18152 log_reader.cc:385] T 340bbfee30af49f3baf400d2973a1515: removed 1 log segments from log reader
I20260812 06:18:34.604332 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000001 (ops 1-6)
I20260812 06:18:34.606956 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: LogGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.003s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:18:34.607323 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:34.624439 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.625233 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:34.781628 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.156s	user 0.130s	sys 0.024s 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":604,"lbm_read_time_us":8869,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30500,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":362,"threads_started":5,"update_count":2000}
I20260812 06:18:34.782176 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:34.842963 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.061s	user 0.037s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23214,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:34.843636 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515): 12308958 bytes on disk
I20260812 06:18:34.844336 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.844859 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:34.859586 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.860320 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:34.999424 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.139s	user 0.112s	sys 0.026s 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":1180,"lbm_read_time_us":9924,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27630,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:18:35.000195 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:35.045356 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.045s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17667,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.046001 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:35.063740 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.064457 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:35.214028 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.149s	user 0.113s	sys 0.036s 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":726,"lbm_read_time_us":9317,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31181,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:35.214819 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:35.277300 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.062s	user 0.028s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22738,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.277860 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:35.297500 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.298156 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:35.476864 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.178s	user 0.109s	sys 0.063s 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":196,"lbm_read_time_us":13895,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29019,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28800,"update_count":2000}
I20260812 06:18:35.477816 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:35.540516 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.062s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.541071 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:35.554234 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.555123 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:35.708273 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.153s	user 0.129s	sys 0.017s 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":979,"lbm_read_time_us":10876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28678,"lbm_writes_lt_1ms":443,"mutex_wait_us":105,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:18:35.709060 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:35.761744 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.053s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.762290 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:35.775437 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.009s	sys 0.003s 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:18:35.776219 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:35.943538 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.167s	user 0.138s	sys 0.028s 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":1048,"lbm_read_time_us":12921,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32258,"lbm_writes_lt_1ms":443,"mutex_wait_us":521,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":2000}
I20260812 06:18:35.944327 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:35.990132 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.046s	user 0.038s	sys 0.004s Metrics: {"bytes_written":12307530,"delete_count":0,"lbm_write_time_us":20112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.990835 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:36.011265 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.020s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.011881 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushMRSOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:36.048707 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushMRSOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.037s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":281,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2366,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:36.049790 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling LogGCOp(340bbfee30af49f3baf400d2973a1515): free 120553370 bytes of WAL
I20260812 06:18:36.050035 18152 log_reader.cc:385] T 340bbfee30af49f3baf400d2973a1515: removed 12 log segments from log reader
I20260812 06:18:36.050084 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000002 (ops 7-11)
I20260812 06:18:36.050138 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000003 (ops 12-16)
I20260812 06:18:36.050185 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000004 (ops 17-21)
I20260812 06:18:36.050230 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000005 (ops 22-26)
I20260812 06:18:36.050271 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000006 (ops 27-31)
I20260812 06:18:36.050318 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000007 (ops 32-36)
I20260812 06:18:36.050359 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000008 (ops 37-40)
I20260812 06:18:36.050400 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000009 (ops 41-45)
I20260812 06:18:36.050436 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000010 (ops 46-50)
I20260812 06:18:36.050474 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000011 (ops 51-54)
I20260812 06:18:36.050521 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000012 (ops 55-59)
I20260812 06:18:36.050562 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000013 (ops 60-64)
I20260812 06:18:36.077950 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: LogGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:36.078552 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515): 448 bytes on disk
I20260812 06:18:36.079365 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.080032 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:36.106109 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.106690 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:36.118664 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.119194 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:36.343963 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.225s	user 0.143s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836414,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1624,"lbm_read_time_us":17722,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40049,"lbm_writes_lt_1ms":643,"mutex_wait_us":299,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:18:36.345842 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=14.095187
I20260812 06:18:36.405900 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.060s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25889,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.406698 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:36.578694 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.172s	user 0.128s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":353,"lbm_read_time_us":12977,"lbm_reads_lt_1ms":463,"lbm_write_time_us":31983,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:36.579465 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=11.118625
I20260812 06:18:36.624228 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.045s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18934,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.624971 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:36.643237 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6185,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.643754 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:36.789852 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.146s	user 0.121s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":10322,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27441,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23168,"update_count":2000}
I20260812 06:18:36.790835 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:36.834787 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.043s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19292,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.835389 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:36.847802 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.848591 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.002825 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.154s	user 0.117s	sys 0.035s 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":386,"lbm_read_time_us":9745,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30401,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:18:37.003666 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:37.049369 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.044s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17338,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.049999 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:37.067836 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.068718 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.209453 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.140s	user 0.096s	sys 0.044s 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":389,"lbm_read_time_us":10721,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26734,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2000}
I20260812 06:18:37.210235 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:37.265713 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.055s	user 0.029s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20072,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.266481 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:37.283752 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.284413 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.454759 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.170s	user 0.103s	sys 0.064s 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":555,"lbm_read_time_us":13093,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30123,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:18:37.455664 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:37.500231 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.044s	user 0.012s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16132,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.501015 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.629566 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.128s	user 0.111s	sys 0.017s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":351,"lbm_read_time_us":8296,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23682,"lbm_writes_lt_1ms":343,"mutex_wait_us":26,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":1500}
I20260812 06:18:37.630419 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:37.669381 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.039s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16510,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.669968 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushMRSOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.717702 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushMRSOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.048s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":493,"dirs.run_wall_time_us":1869,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1986,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:37.718597 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=3.181125
I20260812 06:18:37.733530 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5140,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.734187 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling LogGCOp(340bbfee30af49f3baf400d2973a1515): free 120100325 bytes of WAL
I20260812 06:18:37.734424 18152 log_reader.cc:385] T 340bbfee30af49f3baf400d2973a1515: removed 12 log segments from log reader
I20260812 06:18:37.734479 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000014 (ops 65-68)
I20260812 06:18:37.734526 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000015 (ops 69-73)
I20260812 06:18:37.734562 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000016 (ops 74-78)
I20260812 06:18:37.734599 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000017 (ops 79-82)
I20260812 06:18:37.734632 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000018 (ops 83-87)
I20260812 06:18:37.734666 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000019 (ops 88-92)
I20260812 06:18:37.734700 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000020 (ops 93-97)
I20260812 06:18:37.734730 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000021 (ops 98-102)
I20260812 06:18:37.734760 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000022 (ops 103-107)
I20260812 06:18:37.734791 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000023 (ops 108-112)
I20260812 06:18:37.734822 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000024 (ops 113-116)
I20260812 06:18:37.734856 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000025 (ops 117-121)
I20260812 06:18:37.767668 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: LogGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.033s	user 0.001s	sys 0.032s Metrics: {}
I20260812 06:18:37.768162 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:37.784026 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5580,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.784667 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:37.967267 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.182s	user 0.138s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1341,"lbm_read_time_us":11557,"lbm_reads_lt_1ms":565,"lbm_write_time_us":32349,"lbm_writes_lt_1ms":543,"mutex_wait_us":953,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":96,"threads_started":1,"update_count":2500}
I20260812 06:18:37.968081 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=14.095187
I20260812 06:18:38.030206 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.062s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25835,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.030766 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515): 463 bytes on disk
I20260812 06:18:38.031338 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.032032 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:38.214672 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.182s	user 0.114s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1383,"lbm_read_time_us":12664,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29046,"lbm_writes_lt_1ms":443,"mutex_wait_us":392,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.215420 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=14.095187
I20260812 06:18:38.277428 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.062s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26351,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.278005 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:38.291414 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.292068 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:38.513429 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.221s	user 0.125s	sys 0.081s 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":736,"lbm_read_time_us":13154,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35678,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:38.514158 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=14.095187
I20260812 06:18:38.570057 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.056s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22244,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.570720 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:38.585415 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.586366 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:38.768046 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.181s	user 0.133s	sys 0.048s 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":316,"lbm_read_time_us":13404,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36390,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2500}
I20260812 06:18:38.768829 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=11.118625
I20260812 06:18:38.808993 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.040s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":17794,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1550}
I20260812 06:18:38.809731 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:38.827561 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6997,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.828145 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:38.975579 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.147s	user 0.107s	sys 0.040s 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":275,"lbm_read_time_us":11310,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27419,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.976874 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:39.020164 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.043s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16791,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.020825 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:39.032765 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.033493 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:39.183525 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.150s	user 0.122s	sys 0.027s 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":952,"lbm_read_time_us":10960,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30728,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2000}
I20260812 06:18:39.184391 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:39.240980 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.056s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20227,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.241725 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:39.254873 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.255537 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:39.432467 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.177s	user 0.139s	sys 0.037s 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":264,"lbm_read_time_us":14749,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30808,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:18:39.433151 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=10.126437
I20260812 06:18:39.483778 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.050s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.484572 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:39.497539 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.498373 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushMRSOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:39.536449 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushMRSOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.038s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2013,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:39.537447 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling LogGCOp(340bbfee30af49f3baf400d2973a1515): free 133024614 bytes of WAL
I20260812 06:18:39.537750 18152 log_reader.cc:385] T 340bbfee30af49f3baf400d2973a1515: removed 13 log segments from log reader
I20260812 06:18:39.537827 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000026 (ops 122-126)
I20260812 06:18:39.537889 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000027 (ops 127-131)
I20260812 06:18:39.537947 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000028 (ops 132-136)
I20260812 06:18:39.537992 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000029 (ops 137-141)
I20260812 06:18:39.538030 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000030 (ops 142-146)
I20260812 06:18:39.538070 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000031 (ops 147-151)
I20260812 06:18:39.538116 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000032 (ops 152-156)
I20260812 06:18:39.538158 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000033 (ops 157-161)
I20260812 06:18:39.538196 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000034 (ops 162-166)
I20260812 06:18:39.538235 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000035 (ops 167-170)
I20260812 06:18:39.538275 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000036 (ops 171-175)
I20260812 06:18:39.538314 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000037 (ops 176-180)
I20260812 06:18:39.538353 18152 log.cc:1079] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/340bbfee30af49f3baf400d2973a1515/wal-000000038 (ops 181-185)
I20260812 06:18:39.569574 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: LogGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:39.570451 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515): 482 bytes on disk
I20260812 06:18:39.571156 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: UndoDeltaBlockGCOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.572060 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=4.173312
I20260812 06:18:39.602108 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.030s	user 0.014s	sys 0.013s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":8460,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:39.602967 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=1.196750
I20260812 06:18:39.616957 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":4463,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:18:39.617599 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:39.844678 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.227s	user 0.143s	sys 0.078s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":889,"lbm_read_time_us":16591,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38931,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19200,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:18:39.845542 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=14.095187
I20260812 06:18:39.915432 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.068s	user 0.036s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22732,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.916124 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=2.188937
I20260812 06:18:39.928875 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.929414 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515): perf score=1.000000
I20260812 06:18:40.054895 17997 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.763s	user 2.146s	sys 0.199s
I20260812 06:18:40.121649 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: MajorDeltaCompactionOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.192s	user 0.106s	sys 0.086s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":388,"lbm_read_time_us":15026,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33667,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:40.122519 18259 maintenance_manager.cc:419] P 25f0112a75c8465bb37460d99a5cf91a: Scheduling FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515): perf score=6.157687
I20260812 06:18:40.137992 17997 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.002s	sys 0.000s
I20260812 06:18:40.138903 17997 tablet_server.cc:179] TabletServer@127.17.147.65:0 shutting down...
I20260812 06:18:40.154389 18152 maintenance_manager.cc:643] P 25f0112a75c8465bb37460d99a5cf91a: FlushDeltaMemStoresOp(340bbfee30af49f3baf400d2973a1515) complete. Timing: real 0.032s	user 0.014s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13551,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:18:40.155073 17997 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:40.155578 17997 tablet_replica.cc:333] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a: stopping tablet replica
I20260812 06:18:40.155843 17997 raft_consensus.cc:2243] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.156086 17997 raft_consensus.cc:2272] T 340bbfee30af49f3baf400d2973a1515 P 25f0112a75c8465bb37460d99a5cf91a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.172333 17997 tablet_server.cc:196] TabletServer@127.17.147.65:0 shutdown complete.
I20260812 06:18:40.178284 17997 master.cc:562] Master@127.17.147.126:40933 shutting down...
I20260812 06:18:40.182142 17997 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.182325 17997 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.182384 17997 tablet_replica.cc:333] T 00000000000000000000000000000000 P 71756be5e8154a71811097603778281e: stopping tablet replica
I20260812 06:18:40.195158 17997 master.cc:584] Master@127.17.147.126:40933 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6308 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:40.305540 17997 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.147.126:39083
I20260812 06:18:40.306011 17997 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.308740 18311 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.308799 18316 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.308861 17997 server_base.cc:1061] running on GCE node
W20260812 06:18:40.308811 18310 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.309147 17997 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.309193 17997 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.309240 17997 hybrid_clock.cc:648] HybridClock initialized: now 1786515520309239 us; error 0 us; skew 500 ppm
I20260812 06:18:40.310206 17997 webserver.cc:533] Webserver started at http://127.17.147.126:45065/ using document root <none> and password file <none>
I20260812 06:18:40.310411 17997 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.310484 17997 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.310581 17997 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.311144 17997 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/master-0-root/instance:
uuid: "545ba139c2794ae89c69741ca8507464"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nfb5"
I20260812 06:18:40.312762 17997 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:40.313752 18321 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.314024 17997 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.314106 17997 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/master-0-root
uuid: "545ba139c2794ae89c69741ca8507464"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nfb5"
I20260812 06:18:40.314165 17997 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.323115 17997 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.323427 17997 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.327986 17997 rpc_server.cc:307] RPC server started. Bound to: 127.17.147.126:39083
I20260812 06:18:40.328022 18410 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.147.126:39083 every 8 connection(s)
I20260812 06:18:40.330130 18411 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.333205 18411 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464: Bootstrap starting.
I20260812 06:18:40.334002 18411 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.335083 18411 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464: No bootstrap required, opened a new log
I20260812 06:18:40.335492 18411 raft_consensus.cc:359] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "545ba139c2794ae89c69741ca8507464" member_type: VOTER }
I20260812 06:18:40.335582 18411 raft_consensus.cc:385] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.335604 18411 raft_consensus.cc:740] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 545ba139c2794ae89c69741ca8507464, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.335717 18411 consensus_queue.cc:260] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [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: "545ba139c2794ae89c69741ca8507464" member_type: VOTER }
I20260812 06:18:40.335776 18411 raft_consensus.cc:399] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.335800 18411 raft_consensus.cc:493] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.335829 18411 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.336520 18411 raft_consensus.cc:515] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "545ba139c2794ae89c69741ca8507464" member_type: VOTER }
I20260812 06:18:40.336637 18411 leader_election.cc:304] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [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: 545ba139c2794ae89c69741ca8507464; no voters: 
I20260812 06:18:40.336781 18411 leader_election.cc:290] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.336901 18414 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.337146 18414 raft_consensus.cc:697] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 1 LEADER]: Becoming Leader. State: Replica: 545ba139c2794ae89c69741ca8507464, State: Running, Role: LEADER
I20260812 06:18:40.337337 18411 sys_catalog.cc:565] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.337321 18414 consensus_queue.cc:237] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [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: "545ba139c2794ae89c69741ca8507464" member_type: VOTER }
I20260812 06:18:40.337838 18418 sys_catalog.cc:455] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 545ba139c2794ae89c69741ca8507464. Latest consensus state: current_term: 1 leader_uuid: "545ba139c2794ae89c69741ca8507464" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "545ba139c2794ae89c69741ca8507464" member_type: VOTER } }
I20260812 06:18:40.337826 18417 sys_catalog.cc:455] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "545ba139c2794ae89c69741ca8507464" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "545ba139c2794ae89c69741ca8507464" member_type: VOTER } }
I20260812 06:18:40.337971 18418 sys_catalog.cc:458] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.338035 18417 sys_catalog.cc:458] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.338668 18426 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.339488 18426 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.339673 17997 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.341441 18426 catalog_manager.cc:1383] Generated new cluster ID: 384ee66447b946909cfe0f744848536b
I20260812 06:18:40.341499 18426 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.357244 18426 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.357873 18426 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.363598 18426 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464: Generated new TSK 0
I20260812 06:18:40.363792 18426 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.372030 17997 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.374579 18446 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.374665 17997 server_base.cc:1061] running on GCE node
W20260812 06:18:40.374580 18445 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:40.374579 18449 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:40.375120 17997 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.375181 17997 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:40.375200 17997 hybrid_clock.cc:648] HybridClock initialized: now 1786515520375199 us; error 0 us; skew 500 ppm
I20260812 06:18:40.376184 17997 webserver.cc:533] Webserver started at http://127.17.147.65:45155/ using document root <none> and password file <none>
I20260812 06:18:40.376384 17997 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.376461 17997 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.376547 17997 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.377009 17997 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/instance:
uuid: "55873efe895c40b3a76e23138fc3259c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nfb5"
I20260812 06:18:40.379138 17997 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:40.380244 18456 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.380524 17997 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.380615 17997 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root
uuid: "55873efe895c40b3a76e23138fc3259c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-nfb5"
I20260812 06:18:40.380702 17997 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:40.417348 17997 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.419592 17997 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.421429 17997 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.422466 17997 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.422514 17997 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.422559 17997 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.422612 17997 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.429522 17997 rpc_server.cc:307] RPC server started. Bound to: 127.17.147.65:43061
I20260812 06:18:40.431280 18559 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.147.65:43061 every 8 connection(s)
I20260812 06:18:40.436971 18560 heartbeater.cc:344] Connected to a master server at 127.17.147.126:39083
I20260812 06:18:40.437099 18560 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.437356 18560 heartbeater.cc:507] Master 127.17.147.126:39083 requested a full tablet report, sending...
I20260812 06:18:40.438256 18346 ts_manager.cc:194] Registered new tserver with Master: 55873efe895c40b3a76e23138fc3259c (127.17.147.65:43061)
I20260812 06:18:40.438289 17997 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007816696s
I20260812 06:18:40.439476 18346 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34010
I20260812 06:18:40.447738 18346 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34020:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:40.458114 18505 tablet_service.cc:1511] Processing CreateTablet for tablet cf614f7924dc4c028ab5ba8c0688831e (DEFAULT_TABLE table=heavy-update-compaction-test [id=df5dc68800f4419d9f228ecfee0fef2d]), partition=
I20260812 06:18:40.458465 18505 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cf614f7924dc4c028ab5ba8c0688831e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.460709 18581 tablet_bootstrap.cc:492] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Bootstrap starting.
I20260812 06:18:40.461796 18581 tablet_bootstrap.cc:654] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.463016 18581 tablet_bootstrap.cc:492] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: No bootstrap required, opened a new log
I20260812 06:18:40.463140 18581 ts_tablet_manager.cc:1403] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:40.463652 18581 raft_consensus.cc:359] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55873efe895c40b3a76e23138fc3259c" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 43061 } }
I20260812 06:18:40.463776 18581 raft_consensus.cc:385] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.463841 18581 raft_consensus.cc:740] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 55873efe895c40b3a76e23138fc3259c, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.464026 18581 consensus_queue.cc:260] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [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: "55873efe895c40b3a76e23138fc3259c" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 43061 } }
I20260812 06:18:40.464176 18581 raft_consensus.cc:399] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.464224 18581 raft_consensus.cc:493] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.464282 18581 raft_consensus.cc:3060] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.465082 18581 raft_consensus.cc:515] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55873efe895c40b3a76e23138fc3259c" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 43061 } }
I20260812 06:18:40.465247 18581 leader_election.cc:304] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [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: 55873efe895c40b3a76e23138fc3259c; no voters: 
I20260812 06:18:40.465484 18581 leader_election.cc:290] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.465631 18584 raft_consensus.cc:2804] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.465853 18584 raft_consensus.cc:697] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 1 LEADER]: Becoming Leader. State: Replica: 55873efe895c40b3a76e23138fc3259c, State: Running, Role: LEADER
I20260812 06:18:40.465888 18560 heartbeater.cc:499] Master 127.17.147.126:39083 was elected leader, sending a full tablet report...
I20260812 06:18:40.465859 18581 ts_tablet_manager.cc:1434] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:40.466038 18584 consensus_queue.cc:237] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [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: "55873efe895c40b3a76e23138fc3259c" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 43061 } }
I20260812 06:18:40.467651 18346 catalog_manager.cc:5719] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c reported cstate change: term changed from 0 to 1, leader changed from <none> to 55873efe895c40b3a76e23138fc3259c (127.17.147.65). New cstate: current_term: 1 leader_uuid: "55873efe895c40b3a76e23138fc3259c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "55873efe895c40b3a76e23138fc3259c" member_type: VOTER last_known_addr { host: "127.17.147.65" port: 43061 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.533564 17997 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.022s	sys 0.003s
I20260812 06:18:40.681474 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=15.086190
I20260812 06:18:40.819412 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.138s	user 0.094s	sys 0.043s Metrics: {"bytes_written":8615324,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":953,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34950,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":6144,"update_count":1050}
I20260812 06:18:40.820143 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling LogGCOp(cf614f7924dc4c028ab5ba8c0688831e): free 11976772 bytes of WAL
I20260812 06:18:40.820402 18462 log_reader.cc:385] T cf614f7924dc4c028ab5ba8c0688831e: removed 1 log segments from log reader
I20260812 06:18:40.820453 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000001 (ops 1-6)
I20260812 06:18:40.823495 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: LogGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:40.824268 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:40.842336 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6195,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.842962 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e): 12308959 bytes on disk
I20260812 06:18:40.843454 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e) 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,"spinlock_wait_cycles":1408}
I20260812 06:18:40.843912 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:40.997737 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.154s	user 0.107s	sys 0.044s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528892,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":642,"lbm_read_time_us":10662,"lbm_reads_lt_1ms":360,"lbm_write_time_us":24506,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":387,"threads_started":5,"update_count":1500}
I20260812 06:18:40.998459 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:41.039587 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.041s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16281,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.040258 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:41.167878 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":264,"lbm_read_time_us":8597,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23176,"lbm_writes_lt_1ms":343,"mutex_wait_us":92,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":1500}
I20260812 06:18:41.168669 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:41.217397 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.049s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.218093 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:41.237885 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.238675 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:41.410825 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.172s	user 0.119s	sys 0.052s 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":1155,"lbm_read_time_us":15033,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28379,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:41.411768 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:41.460638 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.049s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17170,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.461256 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:41.473733 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.474277 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:41.637637 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.163s	user 0.115s	sys 0.036s 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":558,"lbm_read_time_us":10627,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31734,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:18:41.638485 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:41.697759 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.059s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21092,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.698352 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:41.710490 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.711170 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:41.855827 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.144s	user 0.112s	sys 0.032s 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":321,"lbm_read_time_us":10800,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29471,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:18:41.856384 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:41.913178 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.057s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":19877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.913782 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:41.925884 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.926487 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:42.067924 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.141s	user 0.097s	sys 0.043s 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":362,"lbm_read_time_us":9527,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26741,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":130432,"update_count":2000}
I20260812 06:18:42.068790 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:42.125542 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.056s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17166,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.126261 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:42.139292 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.139849 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:42.311861 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.172s	user 0.107s	sys 0.064s 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":1028,"lbm_read_time_us":13295,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29306,"lbm_writes_lt_1ms":443,"mutex_wait_us":285,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:42.312508 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:42.366175 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.053s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17931,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.366822 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:42.379346 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.380219 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:42.409893 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1459,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1870,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:42.410718 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling LogGCOp(cf614f7924dc4c028ab5ba8c0688831e): free 121006424 bytes of WAL
I20260812 06:18:42.411046 18462 log_reader.cc:385] T cf614f7924dc4c028ab5ba8c0688831e: removed 12 log segments from log reader
I20260812 06:18:42.411142 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000002 (ops 7-11)
I20260812 06:18:42.411213 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000003 (ops 12-16)
I20260812 06:18:42.411274 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000004 (ops 17-21)
I20260812 06:18:42.411315 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000005 (ops 22-26)
I20260812 06:18:42.411353 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000006 (ops 27-31)
I20260812 06:18:42.411391 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000007 (ops 32-36)
I20260812 06:18:42.411430 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000008 (ops 37-41)
I20260812 06:18:42.411468 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000009 (ops 42-46)
I20260812 06:18:42.411504 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000010 (ops 47-50)
I20260812 06:18:42.411542 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000011 (ops 51-55)
I20260812 06:18:42.411580 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000012 (ops 56-60)
I20260812 06:18:42.411625 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000013 (ops 61-65)
I20260812 06:18:42.439729 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: LogGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:42.440244 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e): 472 bytes on disk
I20260812 06:18:42.440824 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.441375 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=3.181125
I20260812 06:18:42.467388 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.026s	user 0.010s	sys 0.015s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5454,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.468042 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:42.485709 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6534,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.486478 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:42.728246 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.242s	user 0.162s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":476,"lbm_read_time_us":17703,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41509,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:18:42.728969 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:42.806329 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.077s	user 0.031s	sys 0.043s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28795,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.807351 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:42.833398 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.026s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.834076 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:43.028920 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.195s	user 0.097s	sys 0.097s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":15395,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31904,"lbm_writes_lt_1ms":543,"mutex_wait_us":340,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:43.029831 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:43.083704 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.054s	user 0.042s	sys 0.010s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24032,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.084367 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:43.110844 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.026s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.111639 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:43.314209 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.202s	user 0.129s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":927,"lbm_read_time_us":13950,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35086,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:18:43.314772 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:43.376854 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.062s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28225,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.377628 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:43.397505 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.398031 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:43.596019 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.198s	user 0.116s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":11371,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32490,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:18:43.596939 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:43.652057 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.055s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24317,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.652825 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:43.673009 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.674023 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:43.855047 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.181s	user 0.143s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35048,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:18:43.858069 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=11.118625
I20260812 06:18:43.898119 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.040s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16451,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.898816 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:43.914604 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.915205 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:44.063647 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.148s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":10681,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27366,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26880,"update_count":2000}
I20260812 06:18:44.064644 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:44.113094 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.048s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16682,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.113695 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:44.128844 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.015s	user 0.011s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.129613 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:44.164399 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":285,"dirs.run_wall_time_us":1311,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2171,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:44.165191 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling LogGCOp(cf614f7924dc4c028ab5ba8c0688831e): free 133024368 bytes of WAL
I20260812 06:18:44.165455 18462 log_reader.cc:385] T cf614f7924dc4c028ab5ba8c0688831e: removed 13 log segments from log reader
I20260812 06:18:44.165519 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000014 (ops 66-70)
I20260812 06:18:44.165581 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000015 (ops 71-75)
I20260812 06:18:44.165630 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000016 (ops 76-80)
I20260812 06:18:44.165664 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000017 (ops 81-84)
I20260812 06:18:44.165706 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000018 (ops 85-89)
I20260812 06:18:44.165751 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000019 (ops 90-94)
I20260812 06:18:44.165788 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000020 (ops 95-99)
I20260812 06:18:44.165855 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000021 (ops 100-104)
I20260812 06:18:44.165884 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000022 (ops 105-109)
I20260812 06:18:44.165923 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000023 (ops 110-114)
I20260812 06:18:44.165961 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000024 (ops 115-119)
I20260812 06:18:44.166002 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000025 (ops 120-124)
I20260812 06:18:44.166045 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000026 (ops 125-129)
I20260812 06:18:44.197275 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: LogGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:44.197819 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:44.214395 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.016s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4184708,"delete_count":0,"lbm_write_time_us":5564,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:18:44.215010 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:44.228022 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4880,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:18:44.228662 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e): 473 bytes on disk
I20260812 06:18:44.229540 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":138,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.230901 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:44.431969 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.201s	user 0.155s	sys 0.044s 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":539,"lbm_read_time_us":15574,"lbm_reads_lt_1ms":674,"lbm_write_time_us":40663,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:18:44.432809 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:44.486575 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.054s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24315,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.487145 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:44.501027 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.501629 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:44.700284 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.198s	user 0.134s	sys 0.059s 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":164,"lbm_read_time_us":12718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":38460,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:44.701112 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:44.764117 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.063s	user 0.027s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27731,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.764768 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:44.948522 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.184s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1114,"lbm_read_time_us":13069,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27320,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:18:44.949258 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:45.006372 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.057s	user 0.049s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25164,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.007081 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:45.019343 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4862,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.019990 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:45.239074 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.218s	user 0.148s	sys 0.060s 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":143,"lbm_read_time_us":13306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36138,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:45.239880 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=11.118625
I20260812 06:18:45.281535 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.041s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16211,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.282461 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:45.295991 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5077,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:45.296579 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:45.452229 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.155s	user 0.115s	sys 0.038s Metrics: {"cfile_cache_miss":438,"cfile_cache_miss_bytes":20877457,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":10668,"lbm_reads_lt_1ms":470,"lbm_write_time_us":33570,"lbm_writes_lt_1ms":449,"mutex_wait_us":303,"peak_mem_usage":50935538,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2030}
I20260812 06:18:45.453118 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:45.491794 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.038s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12061349,"delete_count":0,"lbm_write_time_us":17584,"lbm_writes_lt_1ms":297,"reinsert_count":0,"update_count":1470}
I20260812 06:18:45.492576 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:45.504801 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.505546 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:45.671924 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.166s	user 0.131s	sys 0.035s Metrics: {"cfile_cache_miss":426,"cfile_cache_miss_bytes":20385171,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1631,"lbm_read_time_us":10670,"lbm_reads_lt_1ms":466,"lbm_write_time_us":29467,"lbm_writes_lt_1ms":437,"mutex_wait_us":451,"peak_mem_usage":49402734,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":1970}
I20260812 06:18:45.672662 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=10.126437
I20260812 06:18:45.725119 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23158,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.725816 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:45.759617 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushMRSOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1203,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1666,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:45.760401 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling LogGCOp(cf614f7924dc4c028ab5ba8c0688831e): free 112239516 bytes of WAL
I20260812 06:18:45.760730 18462 log_reader.cc:385] T cf614f7924dc4c028ab5ba8c0688831e: removed 11 log segments from log reader
I20260812 06:18:45.760798 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000027 (ops 130-134)
I20260812 06:18:45.760844 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000028 (ops 135-139)
I20260812 06:18:45.760879 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000029 (ops 140-144)
I20260812 06:18:45.760903 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000030 (ops 145-149)
I20260812 06:18:45.760931 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000031 (ops 150-154)
I20260812 06:18:45.760962 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000032 (ops 155-159)
I20260812 06:18:45.760998 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000033 (ops 160-164)
I20260812 06:18:45.761021 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000034 (ops 165-169)
I20260812 06:18:45.761047 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000035 (ops 170-174)
I20260812 06:18:45.761087 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000036 (ops 175-178)
I20260812 06:18:45.761117 18462 log.cc:1079] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: Deleting log segment in path: /tmp/dist-test-task9kZoHp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515513971127-17997-0/minicluster-data/ts-0-root/wals/cf614f7924dc4c028ab5ba8c0688831e/wal-000000037 (ops 179-183)
I20260812 06:18:45.792119 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: LogGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:45.792686 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e): 446 bytes on disk
I20260812 06:18:45.793395 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: UndoDeltaBlockGCOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.794090 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:45.823271 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.029s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.823776 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:45.835683 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.836131 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:46.046969 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.211s	user 0.113s	sys 0.095s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":794,"lbm_read_time_us":15476,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34537,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":70400,"thread_start_us":109,"threads_started":1,"update_count":2500}
I20260812 06:18:46.047785 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=14.095187
I20260812 06:18:46.108706 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.061s	user 0.027s	sys 0.026s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28816,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.109411 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:46.281388 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.172s	user 0.131s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":351,"lbm_read_time_us":12430,"lbm_reads_lt_1ms":463,"lbm_write_time_us":28793,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":52992,"update_count":2000}
I20260812 06:18:46.282418 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=11.118625
I20260812 06:18:46.308519 17997 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.775s	user 2.161s	sys 0.233s
I20260812 06:18:46.324105 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.041s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19989,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.324749 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=2.188937
I20260812 06:18:46.336246 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: FlushDeltaMemStoresOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.336750 18561 maintenance_manager.cc:419] P 55873efe895c40b3a76e23138fc3259c: Scheduling MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e): perf score=1.000000
I20260812 06:18:46.341791 17997 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.001s	sys 0.000s
I20260812 06:18:46.342399 17997 tablet_server.cc:179] TabletServer@127.17.147.65:0 shutting down...
I20260812 06:18:46.459440 18462 maintenance_manager.cc:643] P 55873efe895c40b3a76e23138fc3259c: MajorDeltaCompactionOp(cf614f7924dc4c028ab5ba8c0688831e) complete. Timing: real 0.122s	user 0.087s	sys 0.035s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":402,"cfile_cache_miss_bytes":16409878,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":7621,"lbm_reads_lt_1ms":418,"lbm_write_time_us":23228,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2000}
I20260812 06:18:46.460374 17997 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.460662 17997 tablet_replica.cc:333] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c: stopping tablet replica
I20260812 06:18:46.460855 17997 raft_consensus.cc:2243] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.461071 17997 raft_consensus.cc:2272] T cf614f7924dc4c028ab5ba8c0688831e P 55873efe895c40b3a76e23138fc3259c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.466007 17997 tablet_server.cc:196] TabletServer@127.17.147.65:0 shutdown complete.
I20260812 06:18:46.498884 17997 master.cc:562] Master@127.17.147.126:39083 shutting down...
I20260812 06:18:46.503053 17997 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.503262 17997 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.503315 17997 tablet_replica.cc:333] T 00000000000000000000000000000000 P 545ba139c2794ae89c69741ca8507464: stopping tablet replica
I20260812 06:18:46.516004 17997 master.cc:584] Master@127.17.147.126:39083 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6329 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12639 ms total)

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