[==========] 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:17:42.946240 22079 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.143.254:36045
I20260812 06:17:42.947309 22079 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:17:42.947968 22079 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:42.954731 22096 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:17:42.954869 22079 server_base.cc:1061] running on GCE node
W20260812 06:17:42.954780 22101 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:17:42.955087 22098 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:17:42.955586 22079 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:42.955681 22079 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:17:42.955729 22079 hybrid_clock.cc:648] HybridClock initialized: now 1786515462955726 us; error 0 us; skew 500 ppm
I20260812 06:17:42.957713 22079 webserver.cc:533] Webserver started at http://127.21.143.254:44895/ using document root <none> and password file <none>
I20260812 06:17:42.958320 22079 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:42.958382 22079 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:42.958633 22079 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:42.960403 22079 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/master-0-root/instance:
uuid: "f62fbe88aff947fc8be7f69d629907ee"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-zr1t"
I20260812 06:17:42.964267 22079 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.006s
I20260812 06:17:42.966563 22113 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:17:42.967612 22079 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:42.967721 22079 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/master-0-root
uuid: "f62fbe88aff947fc8be7f69d629907ee"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-zr1t"
I20260812 06:17:42.967859 22079 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-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:17:42.985302 22079 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:42.986042 22079 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:17:42.986236 22079 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:42.994040 22079 rpc_server.cc:307] RPC server started. Bound to: 127.21.143.254:36045
I20260812 06:17:42.994059 22198 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.143.254:36045 every 8 connection(s)
I20260812 06:17:42.996433 22199 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:17:43.002163 22199 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: Bootstrap starting.
I20260812 06:17:43.004546 22199 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:43.005453 22199 log.cc:826] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:43.007514 22199 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: No bootstrap required, opened a new log
I20260812 06:17:43.010527 22199 raft_consensus.cc:359] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER }
I20260812 06:17:43.010727 22199 raft_consensus.cc:385] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:43.010772 22199 raft_consensus.cc:740] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f62fbe88aff947fc8be7f69d629907ee, State: Initialized, Role: FOLLOWER
I20260812 06:17:43.011332 22199 consensus_queue.cc:260] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [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: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER }
I20260812 06:17:43.011467 22199 raft_consensus.cc:399] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:43.011515 22199 raft_consensus.cc:493] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:43.011600 22199 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:43.012373 22199 raft_consensus.cc:515] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER }
I20260812 06:17:43.012775 22199 leader_election.cc:304] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [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: f62fbe88aff947fc8be7f69d629907ee; no voters: 
I20260812 06:17:43.013057 22199 leader_election.cc:290] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:43.013196 22208 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:43.013487 22208 raft_consensus.cc:697] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 1 LEADER]: Becoming Leader. State: Replica: f62fbe88aff947fc8be7f69d629907ee, State: Running, Role: LEADER
I20260812 06:17:43.013985 22208 consensus_queue.cc:237] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [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: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER }
I20260812 06:17:43.014160 22199 sys_catalog.cc:565] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:43.015817 22211 sys_catalog.cc:455] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [sys.catalog]: SysCatalogTable state changed. Reason: New leader f62fbe88aff947fc8be7f69d629907ee. Latest consensus state: current_term: 1 leader_uuid: "f62fbe88aff947fc8be7f69d629907ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER } }
I20260812 06:17:43.015872 22209 sys_catalog.cc:455] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f62fbe88aff947fc8be7f69d629907ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f62fbe88aff947fc8be7f69d629907ee" member_type: VOTER } }
I20260812 06:17:43.015940 22211 sys_catalog.cc:458] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:43.015971 22209 sys_catalog.cc:458] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:43.016521 22223 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:43.016636 22079 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:43.019439 22223 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:43.024798 22223 catalog_manager.cc:1383] Generated new cluster ID: 01a4dba1b4344e2fbf88dd3e959e95e6
I20260812 06:17:43.024915 22223 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:43.039438 22223 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:43.040297 22223 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:43.055989 22223 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: Generated new TSK 0
I20260812 06:17:43.056890 22223 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:43.088387 22079 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:43.091534 22242 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:17:43.091542 22241 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:17:43.091846 22079 server_base.cc:1061] running on GCE node
W20260812 06:17:43.091619 22246 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:17:43.092116 22079 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:43.092175 22079 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:17:43.092200 22079 hybrid_clock.cc:648] HybridClock initialized: now 1786515463092200 us; error 0 us; skew 500 ppm
I20260812 06:17:43.093204 22079 webserver.cc:533] Webserver started at http://127.21.143.193:42005/ using document root <none> and password file <none>
I20260812 06:17:43.093379 22079 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:43.093436 22079 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:43.093536 22079 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:43.093983 22079 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/instance:
uuid: "866d973069be444ca8a02d3ed97e63ee"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zr1t"
I20260812 06:17:43.095906 22079 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:43.097020 22251 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:17:43.097373 22079 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:43.097476 22079 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root
uuid: "866d973069be444ca8a02d3ed97e63ee"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zr1t"
I20260812 06:17:43.097600 22079 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-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:17:43.105330 22079 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:43.105875 22079 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:43.106421 22079 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:43.107299 22079 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:43.107391 22079 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:43.107474 22079 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:43.107532 22079 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:43.115221 22079 rpc_server.cc:307] RPC server started. Bound to: 127.21.143.193:40917
I20260812 06:17:43.115628 22361 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.143.193:40917 every 8 connection(s)
I20260812 06:17:43.129896 22363 heartbeater.cc:344] Connected to a master server at 127.21.143.254:36045
I20260812 06:17:43.130177 22363 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:43.130731 22363 heartbeater.cc:507] Master 127.21.143.254:36045 requested a full tablet report, sending...
I20260812 06:17:43.132313 22148 ts_manager.cc:194] Registered new tserver with Master: 866d973069be444ca8a02d3ed97e63ee (127.21.143.193:40917)
I20260812 06:17:43.133014 22079 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016886255s
I20260812 06:17:43.133776 22148 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52830
I20260812 06:17:43.143642 22148 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52840:
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:17:43.159233 22294 tablet_service.cc:1511] Processing CreateTablet for tablet f2fa935069024b2b9aea45cf1aa27a3b (DEFAULT_TABLE table=heavy-update-compaction-test [id=c9f9157d268d43f397259559e6c2dff4]), partition=
I20260812 06:17:43.159844 22294 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f2fa935069024b2b9aea45cf1aa27a3b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:43.162844 22385 tablet_bootstrap.cc:492] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Bootstrap starting.
I20260812 06:17:43.164049 22385 tablet_bootstrap.cc:654] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:43.165342 22385 tablet_bootstrap.cc:492] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: No bootstrap required, opened a new log
I20260812 06:17:43.165475 22385 ts_tablet_manager.cc:1403] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:43.166224 22385 raft_consensus.cc:359] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "866d973069be444ca8a02d3ed97e63ee" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 40917 } }
I20260812 06:17:43.166338 22385 raft_consensus.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:43.166365 22385 raft_consensus.cc:740] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 866d973069be444ca8a02d3ed97e63ee, State: Initialized, Role: FOLLOWER
I20260812 06:17:43.166570 22385 consensus_queue.cc:260] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [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: "866d973069be444ca8a02d3ed97e63ee" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 40917 } }
I20260812 06:17:43.166674 22385 raft_consensus.cc:399] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:43.166730 22385 raft_consensus.cc:493] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:43.166839 22385 raft_consensus.cc:3060] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:43.167979 22385 raft_consensus.cc:515] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "866d973069be444ca8a02d3ed97e63ee" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 40917 } }
I20260812 06:17:43.168111 22385 leader_election.cc:304] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [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: 866d973069be444ca8a02d3ed97e63ee; no voters: 
I20260812 06:17:43.168329 22385 leader_election.cc:290] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:43.168444 22389 raft_consensus.cc:2804] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:43.168634 22389 raft_consensus.cc:697] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 1 LEADER]: Becoming Leader. State: Replica: 866d973069be444ca8a02d3ed97e63ee, State: Running, Role: LEADER
I20260812 06:17:43.168735 22385 ts_tablet_manager.cc:1434] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:43.168792 22389 consensus_queue.cc:237] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [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: "866d973069be444ca8a02d3ed97e63ee" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 40917 } }
I20260812 06:17:43.169173 22363 heartbeater.cc:499] Master 127.21.143.254:36045 was elected leader, sending a full tablet report...
I20260812 06:17:43.172020 22148 catalog_manager.cc:5719] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee reported cstate change: term changed from 0 to 1, leader changed from <none> to 866d973069be444ca8a02d3ed97e63ee (127.21.143.193). New cstate: current_term: 1 leader_uuid: "866d973069be444ca8a02d3ed97e63ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "866d973069be444ca8a02d3ed97e63ee" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 40917 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:43.238090 22079 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.016s	sys 0.011s
I20260812 06:17:43.366793 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=15.086190
I20260812 06:17:43.533358 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.166s	user 0.123s	sys 0.036s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":288,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":883,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43180,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":193,"threads_started":1,"update_count":1450}
I20260812 06:17:43.534636 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b): free 20743880 bytes of WAL
I20260812 06:17:43.534987 22260 log_reader.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b: removed 2 log segments from log reader
I20260812 06:17:43.535053 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000001 (ops 1-6)
I20260812 06:17:43.535100 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000002 (ops 7-11)
I20260812 06:17:43.540598 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.006s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:17:43.541024 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b): 12719216 bytes on disk
I20260812 06:17:43.541664 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.542090 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:43.568449 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.026s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.568874 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:43.579348 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.579783 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:43.754720 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.175s	user 0.130s	sys 0.044s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364567,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":702,"lbm_read_time_us":11341,"lbm_reads_lt_1ms":559,"lbm_write_time_us":32879,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":323,"threads_started":5,"update_count":2450}
I20260812 06:17:43.755278 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=10.126437
I20260812 06:17:43.800686 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.045s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16016,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.801222 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:43.816391 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.816946 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:43.941242 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.124s	user 0.112s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":10153,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22722,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":2000}
I20260812 06:17:43.941919 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=10.126437
I20260812 06:17:43.984373 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.042s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15066,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.984941 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:43.995976 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.996644 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:44.121883 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.125s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":771,"lbm_read_time_us":9705,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24245,"lbm_writes_lt_1ms":443,"mutex_wait_us":378,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:17:44.122515 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=10.126437
I20260812 06:17:44.166838 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.044s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17689,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.167356 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:44.183388 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.183832 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:44.343361 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.159s	user 0.089s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":135,"lbm_read_time_us":8337,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25548,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":86656,"update_count":2000}
I20260812 06:17:44.344122 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:44.392902 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.049s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20793,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.393361 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:44.404994 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.405730 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:44.546849 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.141s	user 0.108s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":9584,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31649,"lbm_writes_lt_1ms":543,"mutex_wait_us":592,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:44.547988 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=10.126437
I20260812 06:17:44.588075 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.039s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16956,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.588668 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:44.599524 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.600118 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:44.720361 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.120s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":849,"lbm_read_time_us":9013,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23177,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.722994 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=10.126437
I20260812 06:17:44.764616 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18681,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.765139 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:44.776335 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.776815 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:44.808529 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1546,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:44.809314 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b): free 112239261 bytes of WAL
I20260812 06:17:44.809589 22260 log_reader.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b: removed 11 log segments from log reader
I20260812 06:17:44.809650 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000003 (ops 12-16)
I20260812 06:17:44.809706 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000004 (ops 17-21)
I20260812 06:17:44.809744 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000005 (ops 22-26)
I20260812 06:17:44.809779 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000006 (ops 27-31)
I20260812 06:17:44.809815 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000007 (ops 32-36)
I20260812 06:17:44.809857 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000008 (ops 37-41)
I20260812 06:17:44.809898 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000009 (ops 42-46)
I20260812 06:17:44.809937 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000010 (ops 47-51)
I20260812 06:17:44.809983 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000011 (ops 52-56)
I20260812 06:17:44.810024 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000012 (ops 57-60)
I20260812 06:17:44.810072 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000013 (ops 61-65)
I20260812 06:17:44.837363 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:44.837821 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=3.181125
I20260812 06:17:44.856407 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6939,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:44.856830 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b): free 12017983 bytes of WAL
I20260812 06:17:44.857030 22260 log_reader.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b: removed 1 log segments from log reader
I20260812 06:17:44.857090 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000014 (ops 66-70)
I20260812 06:17:44.859531 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:44.859805 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b): 462 bytes on disk
I20260812 06:17:44.860181 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.860576 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:44.870765 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3530,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.871168 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:45.047230 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.176s	user 0.145s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":282,"lbm_read_time_us":12586,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34276,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:45.047896 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:45.097916 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.050s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.098517 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:45.114090 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.114750 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:45.284766 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.170s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":908,"lbm_read_time_us":10724,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30300,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:17:45.285295 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:45.344352 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.059s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20944,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.344907 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:45.486662 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.142s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":250,"lbm_read_time_us":10549,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23668,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:45.487345 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=11.118625
I20260812 06:17:45.532274 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20127,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.532856 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:45.551494 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.018s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.551946 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:45.561651 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3634,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.562074 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:45.759157 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.197s	user 0.136s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":272,"lbm_read_time_us":13916,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33111,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2500}
I20260812 06:17:45.759902 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:45.814546 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.054s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.815097 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:45.830987 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.016s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.831569 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:45.985560 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.154s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":11119,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29126,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.986356 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=11.118625
I20260812 06:17:46.036175 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.050s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19106,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:46.036682 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:46.052412 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.053169 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:46.073029 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5992,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.073658 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:46.241389 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.167s	user 0.119s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1252,"lbm_read_time_us":13311,"lbm_reads_lt_1ms":565,"lbm_write_time_us":32547,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:46.242108 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:46.297909 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.056s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25419,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.298453 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:46.317448 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.019s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.318074 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:46.369385 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.051s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1804,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:46.370231 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b): free 121459497 bytes of WAL
I20260812 06:17:46.370496 22260 log_reader.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b: removed 12 log segments from log reader
I20260812 06:17:46.370553 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000015 (ops 71-75)
I20260812 06:17:46.370582 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000016 (ops 76-80)
I20260812 06:17:46.370637 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000017 (ops 81-85)
I20260812 06:17:46.370680 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000018 (ops 86-90)
I20260812 06:17:46.370738 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000019 (ops 91-95)
I20260812 06:17:46.370777 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000020 (ops 96-100)
I20260812 06:17:46.370819 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000021 (ops 101-105)
I20260812 06:17:46.370853 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000022 (ops 106-110)
I20260812 06:17:46.370880 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000023 (ops 111-115)
I20260812 06:17:46.370918 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000024 (ops 116-120)
I20260812 06:17:46.370955 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000025 (ops 121-125)
I20260812 06:17:46.370993 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000026 (ops 126-130)
I20260812 06:17:46.397387 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:46.397934 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=7.149875
I20260812 06:17:46.427758 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.030s	user 0.016s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8986,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:46.428336 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:46.445804 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6354,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.446456 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:46.709827 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.263s	user 0.145s	sys 0.116s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082154,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1724,"lbm_read_time_us":17307,"lbm_reads_lt_1ms":874,"lbm_write_time_us":44718,"lbm_writes_lt_1ms":843,"mutex_wait_us":118,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:17:46.710700 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=18.063937
I20260812 06:17:46.781418 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.070s	user 0.038s	sys 0.018s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":28103,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:46.782007 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:46.792737 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.793246 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:47.008623 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.215s	user 0.159s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":15264,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37256,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:47.009584 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:47.081696 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.072s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24967,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.082366 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:47.097925 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.098532 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:47.297056 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.198s	user 0.134s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":859,"lbm_read_time_us":15126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32152,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:17:47.297803 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:47.362349 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.064s	user 0.038s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23987,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.362958 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b): 493 bytes on disk
I20260812 06:17:47.363521 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.364101 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:47.376792 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.377277 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:47.563656 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.186s	user 0.116s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":157,"lbm_read_time_us":13393,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29778,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:17:47.564255 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:47.627725 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.063s	user 0.024s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22711,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.628274 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:47.639462 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.639997 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:47.831460 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.191s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":367,"lbm_read_time_us":14456,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30378,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:17:47.832041 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=14.095187
I20260812 06:17:47.883288 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.051s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19408,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.883814 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:47.905596 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.022s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.906193 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:47.937175 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushMRSOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1300,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1616,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:47.937960 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b): free 124257449 bytes of WAL
I20260812 06:17:47.938246 22260 log_reader.cc:385] T f2fa935069024b2b9aea45cf1aa27a3b: removed 12 log segments from log reader
I20260812 06:17:47.938311 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000027 (ops 131-135)
I20260812 06:17:47.938350 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000028 (ops 136-140)
I20260812 06:17:47.938380 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000029 (ops 141-145)
I20260812 06:17:47.938413 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000030 (ops 146-150)
I20260812 06:17:47.938444 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000031 (ops 151-155)
I20260812 06:17:47.938482 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000032 (ops 156-160)
I20260812 06:17:47.938512 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000033 (ops 161-165)
I20260812 06:17:47.938539 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000034 (ops 166-170)
I20260812 06:17:47.938570 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000035 (ops 171-175)
I20260812 06:17:47.938602 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000036 (ops 176-180)
I20260812 06:17:47.938629 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000037 (ops 181-184)
I20260812 06:17:47.938658 22260 log.cc:1079] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/f2fa935069024b2b9aea45cf1aa27a3b/wal-000000038 (ops 185-189)
I20260812 06:17:47.969653 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: LogGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.031s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:17:47.970155 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b): 447 bytes on disk
I20260812 06:17:47.970758 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: UndoDeltaBlockGCOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.971581 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=3.181125
I20260812 06:17:47.996781 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.025s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7155,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:47.997205 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=2.188937
I20260812 06:17:48.007052 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.007493 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=1.000000
I20260812 06:17:48.235157 22079 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.997s	user 1.801s	sys 0.165s
I20260812 06:17:48.246726 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: MajorDeltaCompactionOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.239s	user 0.152s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":633,"lbm_read_time_us":16184,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38072,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:48.247437 22364 maintenance_manager.cc:419] P 866d973069be444ca8a02d3ed97e63ee: Scheduling FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b): perf score=18.063937
I20260812 06:17:48.291860 22079 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.004s	sys 0.000s
I20260812 06:17:48.292706 22079 tablet_server.cc:179] TabletServer@127.21.143.193:0 shutting down...
I20260812 06:17:48.307633 22260 maintenance_manager.cc:643] P 866d973069be444ca8a02d3ed97e63ee: FlushDeltaMemStoresOp(f2fa935069024b2b9aea45cf1aa27a3b) complete. Timing: real 0.060s	user 0.042s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27157,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.308228 22079 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:48.308600 22079 tablet_replica.cc:333] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee: stopping tablet replica
I20260812 06:17:48.308853 22079 raft_consensus.cc:2243] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.309064 22079 raft_consensus.cc:2272] T f2fa935069024b2b9aea45cf1aa27a3b P 866d973069be444ca8a02d3ed97e63ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.323688 22079 tablet_server.cc:196] TabletServer@127.21.143.193:0 shutdown complete.
I20260812 06:17:48.328351 22079 master.cc:562] Master@127.21.143.254:36045 shutting down...
I20260812 06:17:48.332253 22079 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.332419 22079 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.332492 22079 tablet_replica.cc:333] T 00000000000000000000000000000000 P f62fbe88aff947fc8be7f69d629907ee: stopping tablet replica
I20260812 06:17:48.344942 22079 master.cc:584] Master@127.21.143.254:36045 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5493 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:48.438673 22079 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.143.254:34359
I20260812 06:17:48.439042 22079 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:48.441195 22416 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:17:48.441243 22413 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:17:48.441242 22412 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:17:48.441287 22079 server_base.cc:1061] running on GCE node
I20260812 06:17:48.441653 22079 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:48.441696 22079 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:17:48.441711 22079 hybrid_clock.cc:648] HybridClock initialized: now 1786515468441711 us; error 0 us; skew 500 ppm
I20260812 06:17:48.442561 22079 webserver.cc:533] Webserver started at http://127.21.143.254:43187/ using document root <none> and password file <none>
I20260812 06:17:48.442701 22079 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:48.442744 22079 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:48.442796 22079 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:48.443140 22079 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/master-0-root/instance:
uuid: "c7cc852bbacd4c25b4255ccddfd054be"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-zr1t"
I20260812 06:17:48.444659 22079 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:48.445519 22425 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:17:48.445822 22079 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:48.445888 22079 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/master-0-root
uuid: "c7cc852bbacd4c25b4255ccddfd054be"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-zr1t"
I20260812 06:17:48.445986 22079 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-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:17:48.456821 22079 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:48.457221 22079 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:48.461257 22079 rpc_server.cc:307] RPC server started. Bound to: 127.21.143.254:34359
I20260812 06:17:48.468269 22515 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:17:48.471465 22514 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.143.254:34359 every 8 connection(s)
I20260812 06:17:48.474857 22515 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be: Bootstrap starting.
I20260812 06:17:48.475800 22515 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:48.476948 22515 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be: No bootstrap required, opened a new log
I20260812 06:17:48.477385 22515 raft_consensus.cc:359] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER }
I20260812 06:17:48.477510 22515 raft_consensus.cc:385] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:48.477610 22515 raft_consensus.cc:740] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c7cc852bbacd4c25b4255ccddfd054be, State: Initialized, Role: FOLLOWER
I20260812 06:17:48.477802 22515 consensus_queue.cc:260] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [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: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER }
I20260812 06:17:48.477919 22515 raft_consensus.cc:399] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:48.477967 22515 raft_consensus.cc:493] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:48.478027 22515 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:48.478787 22515 raft_consensus.cc:515] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER }
I20260812 06:17:48.478946 22515 leader_election.cc:304] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [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: c7cc852bbacd4c25b4255ccddfd054be; no voters: 
I20260812 06:17:48.479174 22515 leader_election.cc:290] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:48.479305 22519 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:48.479583 22519 raft_consensus.cc:697] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 1 LEADER]: Becoming Leader. State: Replica: c7cc852bbacd4c25b4255ccddfd054be, State: Running, Role: LEADER
I20260812 06:17:48.479686 22515 sys_catalog.cc:565] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:48.479756 22519 consensus_queue.cc:237] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [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: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER }
I20260812 06:17:48.480262 22523 sys_catalog.cc:455] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c7cc852bbacd4c25b4255ccddfd054be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER } }
I20260812 06:17:48.480293 22524 sys_catalog.cc:455] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [sys.catalog]: SysCatalogTable state changed. Reason: New leader c7cc852bbacd4c25b4255ccddfd054be. Latest consensus state: current_term: 1 leader_uuid: "c7cc852bbacd4c25b4255ccddfd054be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c7cc852bbacd4c25b4255ccddfd054be" member_type: VOTER } }
I20260812 06:17:48.480366 22523 sys_catalog.cc:458] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:48.480382 22524 sys_catalog.cc:458] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:48.480620 22534 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:48.481454 22534 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:48.481751 22079 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:48.483429 22534 catalog_manager.cc:1383] Generated new cluster ID: 84661028572a4b35bb55b2db951e5d5f
I20260812 06:17:48.483475 22534 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:48.496031 22534 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:48.496531 22534 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:48.502187 22534 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be: Generated new TSK 0
I20260812 06:17:48.502336 22534 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:48.514185 22079 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:48.516179 22558 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:17:48.516186 22557 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:17:48.516304 22079 server_base.cc:1061] running on GCE node
W20260812 06:17:48.516288 22560 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:17:48.516690 22079 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:48.516731 22079 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:17:48.516747 22079 hybrid_clock.cc:648] HybridClock initialized: now 1786515468516748 us; error 0 us; skew 500 ppm
I20260812 06:17:48.517583 22079 webserver.cc:533] Webserver started at http://127.21.143.193:34257/ using document root <none> and password file <none>
I20260812 06:17:48.517743 22079 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:48.517788 22079 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:48.517841 22079 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:48.518251 22079 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/instance:
uuid: "8aea347d80f44c388c884a2d35fb3d15"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-zr1t"
I20260812 06:17:48.519731 22079 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:48.520854 22565 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:17:48.521113 22079 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:48.521205 22079 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root
uuid: "8aea347d80f44c388c884a2d35fb3d15"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-zr1t"
I20260812 06:17:48.521296 22079 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-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:17:48.534437 22079 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:48.534842 22079 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:48.535173 22079 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:48.535652 22079 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:48.535713 22079 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:48.535771 22079 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:48.535820 22079 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:48.540185 22079 rpc_server.cc:307] RPC server started. Bound to: 127.21.143.193:42927
I20260812 06:17:48.540221 22671 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.143.193:42927 every 8 connection(s)
I20260812 06:17:48.548877 22672 heartbeater.cc:344] Connected to a master server at 127.21.143.254:34359
I20260812 06:17:48.549024 22672 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:48.549273 22672 heartbeater.cc:507] Master 127.21.143.254:34359 requested a full tablet report, sending...
I20260812 06:17:48.549981 22456 ts_manager.cc:194] Registered new tserver with Master: 8aea347d80f44c388c884a2d35fb3d15 (127.21.143.193:42927)
I20260812 06:17:48.550714 22079 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010076587s
I20260812 06:17:48.550720 22456 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49342
I20260812 06:17:48.557677 22456 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49358:
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:17:48.566884 22616 tablet_service.cc:1511] Processing CreateTablet for tablet 16c883d8dd3440e18050140e60d5420f (DEFAULT_TABLE table=heavy-update-compaction-test [id=0544d4bb5fc64f408c158a05bab4eabe]), partition=
I20260812 06:17:48.567183 22616 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 16c883d8dd3440e18050140e60d5420f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:48.569262 22692 tablet_bootstrap.cc:492] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Bootstrap starting.
I20260812 06:17:48.570205 22692 tablet_bootstrap.cc:654] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:48.571271 22692 tablet_bootstrap.cc:492] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: No bootstrap required, opened a new log
I20260812 06:17:48.571386 22692 ts_tablet_manager.cc:1403] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:48.571810 22692 raft_consensus.cc:359] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aea347d80f44c388c884a2d35fb3d15" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 42927 } }
I20260812 06:17:48.571933 22692 raft_consensus.cc:385] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:48.572019 22692 raft_consensus.cc:740] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8aea347d80f44c388c884a2d35fb3d15, State: Initialized, Role: FOLLOWER
I20260812 06:17:48.572201 22692 consensus_queue.cc:260] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [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: "8aea347d80f44c388c884a2d35fb3d15" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 42927 } }
I20260812 06:17:48.572314 22692 raft_consensus.cc:399] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:48.572361 22692 raft_consensus.cc:493] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:48.572414 22692 raft_consensus.cc:3060] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:48.573190 22692 raft_consensus.cc:515] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aea347d80f44c388c884a2d35fb3d15" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 42927 } }
I20260812 06:17:48.573350 22692 leader_election.cc:304] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [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: 8aea347d80f44c388c884a2d35fb3d15; no voters: 
I20260812 06:17:48.573594 22692 leader_election.cc:290] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:48.573719 22697 raft_consensus.cc:2804] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:48.573939 22697 raft_consensus.cc:697] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 1 LEADER]: Becoming Leader. State: Replica: 8aea347d80f44c388c884a2d35fb3d15, State: Running, Role: LEADER
I20260812 06:17:48.573976 22692 ts_tablet_manager.cc:1434] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:17:48.574024 22672 heartbeater.cc:499] Master 127.21.143.254:34359 was elected leader, sending a full tablet report...
I20260812 06:17:48.574090 22697 consensus_queue.cc:237] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [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: "8aea347d80f44c388c884a2d35fb3d15" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 42927 } }
I20260812 06:17:48.575443 22456 catalog_manager.cc:5719] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8aea347d80f44c388c884a2d35fb3d15 (127.21.143.193). New cstate: current_term: 1 leader_uuid: "8aea347d80f44c388c884a2d35fb3d15" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8aea347d80f44c388c884a2d35fb3d15" member_type: VOTER last_known_addr { host: "127.21.143.193" port: 42927 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:48.636759 22079 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.008s
I20260812 06:17:48.791257 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushMRSOp(16c883d8dd3440e18050140e60d5420f): perf score=19.054940
I20260812 06:17:48.950069 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushMRSOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.159s	user 0.118s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":971,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41173,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:48.950989 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling LogGCOp(16c883d8dd3440e18050140e60d5420f): free 20743880 bytes of WAL
I20260812 06:17:48.951298 22577 log_reader.cc:385] T 16c883d8dd3440e18050140e60d5420f: removed 2 log segments from log reader
I20260812 06:17:48.951370 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000001 (ops 1-6)
I20260812 06:17:48.951421 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000002 (ops 7-11)
I20260812 06:17:48.957793 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: LogGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:48.958300 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:48.976173 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.018s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.976613 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f): 16411394 bytes on disk
I20260812 06:17:48.977046 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.977448 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:49.137419 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.160s	user 0.119s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":627,"lbm_read_time_us":11142,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":333,"threads_started":5,"update_count":2000}
I20260812 06:17:49.138039 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:49.191839 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.054s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18701,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.192322 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:49.202611 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.203014 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:49.375557 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.172s	user 0.098s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":13855,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26483,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:17:49.376168 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:49.436245 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.060s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.436775 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:49.447041 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.447448 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:49.646183 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.199s	user 0.119s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":13583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31315,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:49.646792 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:49.708199 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.061s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20890,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.708782 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:49.719874 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.720299 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:49.934587 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.214s	user 0.126s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":14367,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33886,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:49.935166 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:49.988624 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.053s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19838,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.989108 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:50.001245 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4586,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.001760 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:50.179205 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.177s	user 0.113s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":467,"lbm_read_time_us":10766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27201,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:17:50.179855 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:50.227893 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.048s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.228325 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:50.239500 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.239945 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushMRSOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:50.271271 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushMRSOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1155,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1958,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:50.271952 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling LogGCOp(16c883d8dd3440e18050140e60d5420f): free 115943176 bytes of WAL
I20260812 06:17:50.272226 22577 log_reader.cc:385] T 16c883d8dd3440e18050140e60d5420f: removed 11 log segments from log reader
I20260812 06:17:50.272286 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000003 (ops 12-16)
I20260812 06:17:50.272325 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000004 (ops 17-21)
I20260812 06:17:50.272362 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000005 (ops 22-26)
I20260812 06:17:50.272388 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000006 (ops 27-31)
I20260812 06:17:50.272411 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000007 (ops 32-36)
I20260812 06:17:50.272432 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000008 (ops 37-41)
I20260812 06:17:50.272454 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000009 (ops 42-46)
I20260812 06:17:50.272475 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000010 (ops 47-51)
I20260812 06:17:50.272498 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000011 (ops 52-56)
I20260812 06:17:50.272543 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000012 (ops 57-61)
I20260812 06:17:50.272580 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000013 (ops 62-66)
I20260812 06:17:50.302795 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: LogGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:50.310278 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f): 461 bytes on disk
I20260812 06:17:50.312668 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":1770,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":3}
I20260812 06:17:50.313351 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:50.329090 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.329668 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:50.340167 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.340601 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:50.585871 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.245s	user 0.131s	sys 0.104s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":632,"lbm_read_time_us":17065,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39769,"lbm_writes_lt_1ms":743,"mutex_wait_us":316,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":109,"threads_started":1,"update_count":3500}
I20260812 06:17:50.586612 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=18.063937
I20260812 06:17:50.650128 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.063s	user 0.029s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28243,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:50.650661 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:50.840104 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.189s	user 0.113s	sys 0.076s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774573,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":321,"lbm_read_time_us":14616,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31167,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:50.840883 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:50.900123 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.059s	user 0.027s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18837,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.900604 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:50.911166 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.911625 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:51.091784 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.180s	user 0.114s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1117,"lbm_read_time_us":12781,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29794,"lbm_writes_lt_1ms":543,"mutex_wait_us":541,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:51.092310 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=11.118625
I20260812 06:17:51.140853 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.048s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19201,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.141335 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:51.165383 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.024s	user 0.005s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4088,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.165895 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:51.180141 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5239,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.180902 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:51.366611 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.185s	user 0.116s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":290,"lbm_read_time_us":13808,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30012,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:51.367445 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:51.418979 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.051s	user 0.031s	sys 0.013s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":19963,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.419595 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:51.431571 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.432221 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:51.621696 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.189s	user 0.118s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":314,"lbm_read_time_us":12700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28655,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2500}
I20260812 06:17:51.622385 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:51.669044 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.046s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20500,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.669735 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:51.681485 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.682176 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:51.858791 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.176s	user 0.129s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":956,"lbm_read_time_us":9615,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34964,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:51.859452 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:51.912690 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.053s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.913177 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:51.923974 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4143,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.924424 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushMRSOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:51.955440 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushMRSOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1251,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1688,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:51.956074 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling LogGCOp(16c883d8dd3440e18050140e60d5420f): free 133024372 bytes of WAL
I20260812 06:17:51.956300 22577 log_reader.cc:385] T 16c883d8dd3440e18050140e60d5420f: removed 13 log segments from log reader
I20260812 06:17:51.956346 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000014 (ops 67-71)
I20260812 06:17:51.956377 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000015 (ops 72-76)
I20260812 06:17:51.956437 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000016 (ops 77-81)
I20260812 06:17:51.956493 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000017 (ops 82-86)
I20260812 06:17:51.956538 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000018 (ops 87-91)
I20260812 06:17:51.956595 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000019 (ops 92-96)
I20260812 06:17:51.956619 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000020 (ops 97-101)
I20260812 06:17:51.956657 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000021 (ops 102-106)
I20260812 06:17:51.956694 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000022 (ops 107-111)
I20260812 06:17:51.956736 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000023 (ops 112-116)
I20260812 06:17:51.956774 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000024 (ops 117-121)
I20260812 06:17:51.956807 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000025 (ops 122-126)
I20260812 06:17:51.956842 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000026 (ops 127-130)
I20260812 06:17:51.986532 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: LogGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:51.986981 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f): 493 bytes on disk
I20260812 06:17:51.987411 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f) 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:17:51.987926 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=4.173312
I20260812 06:17:52.013315 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.025s	user 0.010s	sys 0.012s Metrics: {"bytes_written":6112849,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:17:52.013841 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:52.020519 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2198,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:17:52.020956 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:52.241272 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.220s	user 0.149s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979702,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":733,"lbm_read_time_us":15624,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37491,"lbm_writes_lt_1ms":743,"mutex_wait_us":452,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:52.242027 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=15.087375
I20260812 06:17:52.298494 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.056s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":23091,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:52.299027 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:52.310283 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.310714 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:52.320205 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:52.320616 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:52.535701 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.215s	user 0.122s	sys 0.091s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":721,"lbm_read_time_us":15640,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36216,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3000}
I20260812 06:17:52.536419 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=14.095187
I20260812 06:17:52.594977 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.058s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16491952,"delete_count":0,"lbm_write_time_us":25115,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":404,"reinsert_count":0,"update_count":2010}
I20260812 06:17:52.595777 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:52.622438 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.026s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5447,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:52.622929 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:52.637866 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.638361 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:52.853757 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.215s	user 0.127s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":403,"lbm_read_time_us":14748,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33727,"lbm_writes_lt_1ms":643,"mutex_wait_us":79,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:52.854552 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=16.079562
I20260812 06:17:52.926201 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.069s	user 0.026s	sys 0.029s Metrics: {"bytes_written":18789301,"delete_count":0,"lbm_write_time_us":25387,"lbm_writes_lt_1ms":461,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2290}
I20260812 06:17:52.926715 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=4.173312
I20260812 06:17:52.943004 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":5825684,"delete_count":0,"lbm_write_time_us":6488,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:17:52.943634 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:53.151976 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.208s	user 0.124s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":15017,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34423,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29824,"update_count":3000}
I20260812 06:17:53.152599 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=18.063937
I20260812 06:17:53.230083 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.077s	user 0.051s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30467,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:53.230561 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:53.241503 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.242201 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:53.443922 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.202s	user 0.134s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":14568,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32688,"lbm_writes_lt_1ms":643,"mutex_wait_us":117,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":3000}
I20260812 06:17:53.444775 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=15.087375
I20260812 06:17:53.486325 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.041s	user 0.022s	sys 0.019s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":17793,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:53.486994 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:53.510543 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.023s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5030,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.511045 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:53.525691 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.014s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.526209 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushMRSOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:53.560495 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushMRSOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.034s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1510,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1743,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:53.561230 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling LogGCOp(16c883d8dd3440e18050140e60d5420f): free 129320747 bytes of WAL
I20260812 06:17:53.561542 22577 log_reader.cc:385] T 16c883d8dd3440e18050140e60d5420f: removed 13 log segments from log reader
I20260812 06:17:53.561601 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000027 (ops 131-135)
I20260812 06:17:53.561642 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000028 (ops 136-140)
I20260812 06:17:53.561676 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000029 (ops 141-145)
I20260812 06:17:53.561707 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000030 (ops 146-150)
I20260812 06:17:53.561738 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000031 (ops 151-154)
I20260812 06:17:53.561764 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000032 (ops 155-159)
I20260812 06:17:53.561791 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000033 (ops 160-164)
I20260812 06:17:53.561825 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000034 (ops 165-169)
I20260812 06:17:53.561856 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000035 (ops 170-174)
I20260812 06:17:53.561882 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000036 (ops 175-179)
I20260812 06:17:53.561909 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000037 (ops 180-184)
I20260812 06:17:53.561934 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000038 (ops 185-188)
I20260812 06:17:53.561961 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000039 (ops 189-193)
I20260812 06:17:53.596724 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: LogGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.035s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:17:53.597247 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f): 492 bytes on disk
I20260812 06:17:53.597838 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: UndoDeltaBlockGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:17:53.598433 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:53.621356 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.023s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.621963 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling LogGCOp(16c883d8dd3440e18050140e60d5420f): free 12018006 bytes of WAL
I20260812 06:17:53.622217 22577 log_reader.cc:385] T 16c883d8dd3440e18050140e60d5420f: removed 1 log segments from log reader
I20260812 06:17:53.622300 22577 log.cc:1079] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: Deleting log segment in path: /tmp/dist-test-taskpyjMrR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462935431-22079-0/minicluster-data/ts-0-root/wals/16c883d8dd3440e18050140e60d5420f/wal-000000040 (ops 194-198)
I20260812 06:17:53.625072 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: LogGCOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:53.625417 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f): perf score=2.188937
I20260812 06:17:53.636376 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: FlushDeltaMemStoresOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.636839 22674 maintenance_manager.cc:419] P 8aea347d80f44c388c884a2d35fb3d15: Scheduling MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f): perf score=1.000000
I20260812 06:17:53.664768 22079 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.028s	user 1.870s	sys 0.215s
I20260812 06:17:53.764127 22079 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.001s	sys 0.000s
I20260812 06:17:53.764667 22079 tablet_server.cc:179] TabletServer@127.21.143.193:0 shutting down...
I20260812 06:17:53.848012 22577 maintenance_manager.cc:643] P 8aea347d80f44c388c884a2d35fb3d15: MajorDeltaCompactionOp(16c883d8dd3440e18050140e60d5420f) complete. Timing: real 0.211s	user 0.143s	sys 0.068s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082267,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":304,"lbm_read_time_us":17578,"lbm_reads_lt_1ms":871,"lbm_write_time_us":39472,"lbm_writes_lt_1ms":843,"mutex_wait_us":42,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":34688,"thread_start_us":81,"threads_started":1,"update_count":4000}
I20260812 06:17:53.849442 22079 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:53.849938 22079 tablet_replica.cc:333] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15: stopping tablet replica
I20260812 06:17:53.850103 22079 raft_consensus.cc:2243] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:53.850317 22079 raft_consensus.cc:2272] T 16c883d8dd3440e18050140e60d5420f P 8aea347d80f44c388c884a2d35fb3d15 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:53.857625 22079 tablet_server.cc:196] TabletServer@127.21.143.193:0 shutdown complete.
I20260812 06:17:53.920799 22079 master.cc:562] Master@127.21.143.254:34359 shutting down...
I20260812 06:17:53.924458 22079 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:53.924691 22079 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:53.924778 22079 tablet_replica.cc:333] T 00000000000000000000000000000000 P c7cc852bbacd4c25b4255ccddfd054be: stopping tablet replica
I20260812 06:17:53.937498 22079 master.cc:584] Master@127.21.143.254:34359 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5586 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11080 ms total)

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