[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:46.383842 10684 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.111.62:35319
I20260812 06:19:46.384735 10684 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:46.385283 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:46.391047 10694 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.391098 10699 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.391273 10696 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:46.391276 10684 server_base.cc:1061] running on GCE node
I20260812 06:19:46.391697 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:46.391783 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:46.391822 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515586391821 us; error 0 us; skew 500 ppm
I20260812 06:19:46.393363 10684 webserver.cc:533] Webserver started at http://127.10.111.62:37237/ using document root <none> and password file <none>
I20260812 06:19:46.393819 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:46.393874 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:46.394114 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:46.395560 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/master-0-root/instance:
uuid: "083b3fcddfea4c048f7d704b1e7c5610"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-q9h9"
I20260812 06:19:46.398590 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:46.400385 10719 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.401273 10684 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:46.401362 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/master-0-root
uuid: "083b3fcddfea4c048f7d704b1e7c5610"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-q9h9"
I20260812 06:19:46.401443 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:46.412075 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:46.412552 10684 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:46.412683 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:46.419380 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.62:35319
I20260812 06:19:46.419412 10805 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.62:35319 every 8 connection(s)
I20260812 06:19:46.421344 10808 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:46.426317 10808 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: Bootstrap starting.
I20260812 06:19:46.428485 10808 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:46.429302 10808 log.cc:826] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:46.430810 10808 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: No bootstrap required, opened a new log
I20260812 06:19:46.433379 10808 raft_consensus.cc:359] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER }
I20260812 06:19:46.433532 10808 raft_consensus.cc:385] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:46.433599 10808 raft_consensus.cc:740] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 083b3fcddfea4c048f7d704b1e7c5610, State: Initialized, Role: FOLLOWER
I20260812 06:19:46.434131 10808 consensus_queue.cc:260] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [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: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER }
I20260812 06:19:46.434288 10808 raft_consensus.cc:399] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:46.434348 10808 raft_consensus.cc:493] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:46.434458 10808 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:46.435168 10808 raft_consensus.cc:515] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER }
I20260812 06:19:46.435556 10808 leader_election.cc:304] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [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: 083b3fcddfea4c048f7d704b1e7c5610; no voters: 
I20260812 06:19:46.435853 10808 leader_election.cc:290] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:46.435940 10816 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:46.436131 10816 raft_consensus.cc:697] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 1 LEADER]: Becoming Leader. State: Replica: 083b3fcddfea4c048f7d704b1e7c5610, State: Running, Role: LEADER
I20260812 06:19:46.436520 10816 consensus_queue.cc:237] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [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: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER }
I20260812 06:19:46.436698 10808 sys_catalog.cc:565] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:46.438107 10822 sys_catalog.cc:455] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 083b3fcddfea4c048f7d704b1e7c5610. Latest consensus state: current_term: 1 leader_uuid: "083b3fcddfea4c048f7d704b1e7c5610" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER } }
I20260812 06:19:46.438232 10822 sys_catalog.cc:458] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:46.438511 10819 sys_catalog.cc:455] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "083b3fcddfea4c048f7d704b1e7c5610" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "083b3fcddfea4c048f7d704b1e7c5610" member_type: VOTER } }
I20260812 06:19:46.438587 10819 sys_catalog.cc:458] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:46.438902 10684 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:46.440793 10850 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:46.440856 10850 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:46.440933 10841 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:46.441818 10841 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:46.446038 10841 catalog_manager.cc:1383] Generated new cluster ID: 1843078241e94788a36803be621ca8e1
I20260812 06:19:46.446097 10841 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:46.465025 10841 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:46.465735 10841 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:46.485116 10841 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: Generated new TSK 0
I20260812 06:19:46.485612 10841 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:46.503535 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:46.506105 10859 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:46.506217 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:46.506335 10857 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:46.506153 10862 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:46.506598 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:46.506654 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:46.506677 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515586506677 us; error 0 us; skew 500 ppm
I20260812 06:19:46.507601 10684 webserver.cc:533] Webserver started at http://127.10.111.1:34185/ using document root <none> and password file <none>
I20260812 06:19:46.507777 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:46.507853 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:46.507931 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:46.508411 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/instance:
uuid: "bb627c4844c34181a258136b072b1f46"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-q9h9"
I20260812 06:19:46.510391 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:46.511551 10869 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.511852 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:46.511950 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root
uuid: "bb627c4844c34181a258136b072b1f46"
format_stamp: "Formatted at 2026-08-12 06:19:46 on dist-test-slave-q9h9"
I20260812 06:19:46.512035 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:46.541702 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:46.542138 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:46.542613 10684 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:46.543546 10684 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:46.543609 10684 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.543663 10684 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:46.543691 10684 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:46.550040 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.1:45977
I20260812 06:19:46.550079 10984 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.1:45977 every 8 connection(s)
I20260812 06:19:46.564277 10985 heartbeater.cc:344] Connected to a master server at 127.10.111.62:35319
I20260812 06:19:46.564481 10985 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:46.564880 10985 heartbeater.cc:507] Master 127.10.111.62:35319 requested a full tablet report, sending...
I20260812 06:19:46.566283 10746 ts_manager.cc:194] Registered new tserver with Master: bb627c4844c34181a258136b072b1f46 (127.10.111.1:45977)
I20260812 06:19:46.566365 10684 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01569512s
I20260812 06:19:46.567734 10746 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36740
I20260812 06:19:46.575199 10746 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36752:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:46.587595 10922 tablet_service.cc:1511] Processing CreateTablet for tablet 3eb56064098f4d1a9f7af7dbb5d76ce9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bebaff64a8b84e2a9f59e77c9972c3f8]), partition=
I20260812 06:19:46.587954 10922 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3eb56064098f4d1a9f7af7dbb5d76ce9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:46.590510 11012 tablet_bootstrap.cc:492] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Bootstrap starting.
I20260812 06:19:46.591584 11012 tablet_bootstrap.cc:654] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:46.592783 11012 tablet_bootstrap.cc:492] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: No bootstrap required, opened a new log
I20260812 06:19:46.592876 11012 ts_tablet_manager.cc:1403] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:46.593240 11012 raft_consensus.cc:359] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb627c4844c34181a258136b072b1f46" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 45977 } }
I20260812 06:19:46.593333 11012 raft_consensus.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:46.593365 11012 raft_consensus.cc:740] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb627c4844c34181a258136b072b1f46, State: Initialized, Role: FOLLOWER
I20260812 06:19:46.593490 11012 consensus_queue.cc:260] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [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: "bb627c4844c34181a258136b072b1f46" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 45977 } }
I20260812 06:19:46.593582 11012 raft_consensus.cc:399] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:46.593626 11012 raft_consensus.cc:493] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:46.593674 11012 raft_consensus.cc:3060] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:46.594332 11012 raft_consensus.cc:515] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb627c4844c34181a258136b072b1f46" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 45977 } }
I20260812 06:19:46.594455 11012 leader_election.cc:304] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [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: bb627c4844c34181a258136b072b1f46; no voters: 
I20260812 06:19:46.594640 11012 leader_election.cc:290] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:46.594743 11020 raft_consensus.cc:2804] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:46.594967 11012 ts_tablet_manager.cc:1434] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:46.595010 11020 raft_consensus.cc:697] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 1 LEADER]: Becoming Leader. State: Replica: bb627c4844c34181a258136b072b1f46, State: Running, Role: LEADER
I20260812 06:19:46.595139 10985 heartbeater.cc:499] Master 127.10.111.62:35319 was elected leader, sending a full tablet report...
I20260812 06:19:46.595158 11020 consensus_queue.cc:237] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [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: "bb627c4844c34181a258136b072b1f46" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 45977 } }
I20260812 06:19:46.597366 10746 catalog_manager.cc:5719] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 reported cstate change: term changed from 0 to 1, leader changed from <none> to bb627c4844c34181a258136b072b1f46 (127.10.111.1). New cstate: current_term: 1 leader_uuid: "bb627c4844c34181a258136b072b1f46" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb627c4844c34181a258136b072b1f46" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 45977 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:46.657050 10684 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.013s
I20260812 06:19:46.801108 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=19.054940
I20260812 06:19:46.955742 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.154s	user 0.116s	sys 0.036s Metrics: {"bytes_written":12717737,"cfile_init":1,"compiler_manager_pool.queue_time_us":206,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":778,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36719,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":233856,"thread_start_us":104,"threads_started":1,"update_count":1550}
I20260812 06:19:46.956785 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): free 20743880 bytes of WAL
I20260812 06:19:46.957214 10879 log_reader.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9: removed 2 log segments from log reader
I20260812 06:19:46.957397 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000001 (ops 1-6)
I20260812 06:19:46.957554 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000002 (ops 7-11)
I20260812 06:19:46.963220 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:46.963654 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:46.994554 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.031s	user 0.005s	sys 0.016s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5317,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:19:46.994951 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.006388 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:47.006827 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): 16411392 bytes on disk
I20260812 06:19:47.007478 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.007921 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:47.166504 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.158s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774805,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":479,"lbm_read_time_us":10936,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28414,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":346,"threads_started":5,"update_count":2500}
I20260812 06:19:47.166973 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:47.213392 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.046s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18965,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.213901 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.228760 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.229212 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:47.352985 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.124s	user 0.103s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1035,"lbm_read_time_us":9199,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24513,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:19:47.353474 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:47.388590 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.035s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13328,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":1500}
I20260812 06:19:47.389058 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.398789 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.399227 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:47.520320 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.121s	user 0.079s	sys 0.042s 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":175,"lbm_read_time_us":8562,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22167,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:47.520860 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:47.557462 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.036s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15867,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.557911 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.567327 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.567677 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:47.690850 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.123s	user 0.109s	sys 0.014s 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":831,"lbm_read_time_us":8882,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23126,"lbm_writes_lt_1ms":443,"mutex_wait_us":563,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:47.691529 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:47.728677 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12794,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.729131 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.739187 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.739535 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:47.875413 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.136s	user 0.098s	sys 0.035s 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":177,"lbm_read_time_us":10277,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22433,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:19:47.875854 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:47.920179 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.044s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13808,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.920671 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:47.930303 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.930922 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:48.055299 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.124s	user 0.098s	sys 0.026s 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":233,"lbm_read_time_us":8085,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26732,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:48.055933 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=10.126437
I20260812 06:19:48.099279 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.043s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19823,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.099844 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:48.114400 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.114902 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:48.162798 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.048s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1106,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1541,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:48.163697 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): free 115943182 bytes of WAL
I20260812 06:19:48.163923 10879 log_reader.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9: removed 11 log segments from log reader
I20260812 06:19:48.163971 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000003 (ops 12-16)
I20260812 06:19:48.164011 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000004 (ops 17-21)
I20260812 06:19:48.164043 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000005 (ops 22-26)
I20260812 06:19:48.164069 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000006 (ops 27-31)
I20260812 06:19:48.164096 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000007 (ops 32-36)
I20260812 06:19:48.164124 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000008 (ops 37-41)
I20260812 06:19:48.164155 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000009 (ops 42-46)
I20260812 06:19:48.164186 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000010 (ops 47-51)
I20260812 06:19:48.164217 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000011 (ops 52-56)
I20260812 06:19:48.164247 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000012 (ops 57-61)
I20260812 06:19:48.164278 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000013 (ops 62-66)
I20260812 06:19:48.186417 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:48.186836 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=6.157687
I20260812 06:19:48.205466 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.018s	user 0.010s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7576,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:48.205857 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): free 8767067 bytes of WAL
I20260812 06:19:48.206059 10879 log_reader.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9: removed 1 log segments from log reader
I20260812 06:19:48.206104 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000014 (ops 67-71)
I20260812 06:19:48.207589 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:48.207854 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:48.225257 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.225768 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:48.412708 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.187s	user 0.117s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":549,"lbm_read_time_us":13830,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37353,"lbm_writes_lt_1ms":743,"mutex_wait_us":318,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:19:48.413275 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=15.087375
I20260812 06:19:48.460448 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.047s	user 0.027s	sys 0.014s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":19126,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:48.460943 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=3.181125
I20260812 06:19:48.474385 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4594950,"delete_count":0,"lbm_write_time_us":5409,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:19:48.474779 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:48.486997 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:48.487396 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): 473 bytes on disk
I20260812 06:19:48.487778 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.488240 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:48.641539 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.153s	user 0.123s	sys 0.029s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":305,"lbm_read_time_us":12117,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31179,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":3000}
I20260812 06:19:48.642163 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:48.717057 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.075s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":40995,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:48.717530 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=6.157687
I20260812 06:19:48.741596 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.024s	user 0.018s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7925,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:48.742161 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:48.913420 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.171s	user 0.126s	sys 0.045s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":983,"lbm_read_time_us":12568,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36587,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":3000}
I20260812 06:19:48.913889 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:48.954744 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.955359 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:48.967643 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.968127 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:49.124435 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.156s	user 0.132s	sys 0.024s 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":1290,"lbm_read_time_us":10011,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28415,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:49.124946 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:49.163640 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.038s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:49.164254 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:49.302306 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.138s	user 0.102s	sys 0.025s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1345,"lbm_read_time_us":8435,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22143,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:49.302865 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:49.353246 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.353729 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:49.364168 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.364588 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:49.397841 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.033s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1079,"drs_written":1,"lbm_read_time_us":33,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:49.398505 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): free 112239373 bytes of WAL
I20260812 06:19:49.398715 10879 log_reader.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9: removed 11 log segments from log reader
I20260812 06:19:49.398761 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000015 (ops 72-76)
I20260812 06:19:49.398789 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000016 (ops 77-81)
I20260812 06:19:49.398821 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000017 (ops 82-86)
I20260812 06:19:49.398854 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000018 (ops 87-91)
I20260812 06:19:49.398878 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000019 (ops 92-96)
I20260812 06:19:49.398910 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000020 (ops 97-100)
I20260812 06:19:49.398943 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000021 (ops 101-105)
I20260812 06:19:49.398976 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000022 (ops 106-110)
I20260812 06:19:49.399008 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000023 (ops 111-115)
I20260812 06:19:49.399041 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000024 (ops 116-120)
I20260812 06:19:49.399073 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000025 (ops 121-125)
I20260812 06:19:49.420164 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:49.420526 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=3.181125
I20260812 06:19:49.438645 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:49.439076 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): 447 bytes on disk
I20260812 06:19:49.439488 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.440059 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:49.450840 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.451421 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:49.684516 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.233s	user 0.137s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1262,"lbm_read_time_us":16002,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38553,"lbm_writes_lt_1ms":743,"mutex_wait_us":294,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":70,"threads_started":1,"update_count":3500}
I20260812 06:19:49.685002 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=18.063937
I20260812 06:19:49.735592 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.050s	user 0.038s	sys 0.008s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":21104,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:49.736202 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:49.903692 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.167s	user 0.099s	sys 0.068s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774568,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":584,"lbm_read_time_us":12095,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29013,"lbm_writes_lt_1ms":543,"mutex_wait_us":343,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:49.904350 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:49.959928 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.055s	user 0.040s	sys 0.014s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20865,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.960476 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:49.970866 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.971280 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:50.151098 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.180s	user 0.104s	sys 0.071s 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":615,"lbm_read_time_us":15889,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":28938,"lbm_writes_lt_1ms":543,"mutex_wait_us":348,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:19:50.151590 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=11.118625
I20260812 06:19:50.187911 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.036s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15740,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.188678 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.220481 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.032s	user 0.008s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.220950 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.235265 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.235740 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:50.402311 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.166s	user 0.134s	sys 0.028s 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":853,"lbm_read_time_us":12906,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28831,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:50.402853 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=11.118625
I20260812 06:19:50.443138 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.040s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17695,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:50.443619 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.454888 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.455335 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.463964 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3318,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.464461 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:50.641620 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.177s	user 0.102s	sys 0.065s 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":923,"lbm_read_time_us":12392,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28132,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:19:50.642189 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:50.690268 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.048s	user 0.038s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21262,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.690701 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.700836 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.701401 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:50.858675 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.157s	user 0.101s	sys 0.045s 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":111,"lbm_read_time_us":11252,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28860,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:50.859395 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=14.095187
I20260812 06:19:50.903441 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.044s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.903909 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=2.188937
I20260812 06:19:50.914712 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.915294 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:50.943819 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushMRSOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1033,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:50.944434 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): free 128867708 bytes of WAL
I20260812 06:19:50.944651 10879 log_reader.cc:385] T 3eb56064098f4d1a9f7af7dbb5d76ce9: removed 13 log segments from log reader
I20260812 06:19:50.944697 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000026 (ops 126-130)
I20260812 06:19:50.944725 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000027 (ops 131-134)
I20260812 06:19:50.944743 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000028 (ops 135-139)
I20260812 06:19:50.944775 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000029 (ops 140-144)
I20260812 06:19:50.944805 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000030 (ops 145-149)
I20260812 06:19:50.944837 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000031 (ops 150-154)
I20260812 06:19:50.944867 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000032 (ops 155-159)
I20260812 06:19:50.944900 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000033 (ops 160-164)
I20260812 06:19:50.944931 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000034 (ops 165-168)
I20260812 06:19:50.944962 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000035 (ops 169-173)
I20260812 06:19:50.944991 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000036 (ops 174-178)
I20260812 06:19:50.945022 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000037 (ops 179-182)
I20260812 06:19:50.945062 10879 log.cc:1079] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/3eb56064098f4d1a9f7af7dbb5d76ce9/wal-000000038 (ops 183-187)
I20260812 06:19:50.970398 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: LogGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:50.970845 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9): 492 bytes on disk
I20260812 06:19:50.971282 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: UndoDeltaBlockGCOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.971921 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=5.165500
I20260812 06:19:50.997887 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.026s	user 0.002s	sys 0.020s Metrics: {"bytes_written":7138450,"delete_count":0,"lbm_write_time_us":6744,"lbm_writes_lt_1ms":177,"reinsert_count":0,"update_count":870}
I20260812 06:19:50.998404 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:51.173761 10684 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.517s	user 1.608s	sys 0.149s
I20260812 06:19:51.193809 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.195s	user 0.141s	sys 0.053s Metrics: {"cfile_cache_miss":707,"cfile_cache_miss_bytes":31913005,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":15499,"lbm_reads_lt_1ms":739,"lbm_write_time_us":35298,"lbm_writes_lt_1ms":717,"peak_mem_usage":84821366,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3370}
I20260812 06:19:51.194296 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=15.087375
I20260812 06:19:51.236801 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: FlushDeltaMemStoresOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.042s	user 0.028s	sys 0.011s Metrics: {"bytes_written":17476539,"delete_count":0,"lbm_write_time_us":15493,"lbm_writes_lt_1ms":429,"reinsert_count":0,"update_count":2130}
I20260812 06:19:51.237267 10987 maintenance_manager.cc:419] P bb627c4844c34181a258136b072b1f46: Scheduling MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9): perf score=1.000000
I20260812 06:19:51.252542 10684 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.002s	sys 0.000s
I20260812 06:19:51.253280 10684 tablet_server.cc:179] TabletServer@127.10.111.1:0 shutting down...
I20260812 06:19:51.365731 10879 maintenance_manager.cc:643] P bb627c4844c34181a258136b072b1f46: MajorDeltaCompactionOp(3eb56064098f4d1a9f7af7dbb5d76ce9) complete. Timing: real 0.128s	user 0.080s	sys 0.048s Metrics: {"cfile_cache_miss":457,"cfile_cache_miss_bytes":21738795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":333,"lbm_read_time_us":10292,"lbm_reads_lt_1ms":493,"lbm_write_time_us":19704,"lbm_writes_lt_1ms":469,"mutex_wait_us":57,"peak_mem_usage":53837006,"reinsert_count":0,"spinlock_wait_cycles":43264,"update_count":2130}
I20260812 06:19:51.366577 10684 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:51.366914 10684 tablet_replica.cc:333] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46: stopping tablet replica
I20260812 06:19:51.367136 10684 raft_consensus.cc:2243] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:51.367375 10684 raft_consensus.cc:2272] T 3eb56064098f4d1a9f7af7dbb5d76ce9 P bb627c4844c34181a258136b072b1f46 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:51.372056 10684 tablet_server.cc:196] TabletServer@127.10.111.1:0 shutdown complete.
I20260812 06:19:51.405139 10684 master.cc:562] Master@127.10.111.62:35319 shutting down...
I20260812 06:19:51.408269 10684 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:51.408411 10684 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:51.408478 10684 tablet_replica.cc:333] T 00000000000000000000000000000000 P 083b3fcddfea4c048f7d704b1e7c5610: stopping tablet replica
I20260812 06:19:51.420331 10684 master.cc:584] Master@127.10.111.62:35319 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5113 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:51.497133 10684 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.111.62:35787
I20260812 06:19:51.497512 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.499409 11069 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:51.499517 11063 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:51.499529 11064 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:51.499593 10684 server_base.cc:1061] running on GCE node
I20260812 06:19:51.499794 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.499828 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:51.499848 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515591499848 us; error 0 us; skew 500 ppm
I20260812 06:19:51.500634 10684 webserver.cc:533] Webserver started at http://127.10.111.62:39793/ using document root <none> and password file <none>
I20260812 06:19:51.500803 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.500850 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.500927 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.501286 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/master-0-root/instance:
uuid: "9413960c10be47ebb2a54b5939ec0de9"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-q9h9"
I20260812 06:19:51.502971 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:51.503996 11076 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.504272 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:51.504359 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/master-0-root
uuid: "9413960c10be47ebb2a54b5939ec0de9"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-q9h9"
I20260812 06:19:51.504429 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:51.530298 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.530591 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.534387 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.62:35787
I20260812 06:19:51.550896 11188 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:51.550936 11187 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.62:35787 every 8 connection(s)
I20260812 06:19:51.552642 11188 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9: Bootstrap starting.
I20260812 06:19:51.553377 11188 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.554308 11188 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9: No bootstrap required, opened a new log
I20260812 06:19:51.554689 11188 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER }
I20260812 06:19:51.554773 11188 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.554816 11188 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9413960c10be47ebb2a54b5939ec0de9, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.554955 11188 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [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: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER }
I20260812 06:19:51.555027 11188 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.555065 11188 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.555114 11188 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.555764 11188 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER }
I20260812 06:19:51.555889 11188 leader_election.cc:304] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [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: 9413960c10be47ebb2a54b5939ec0de9; no voters: 
I20260812 06:19:51.556056 11188 leader_election.cc:290] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.556142 11193 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.556373 11193 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 1 LEADER]: Becoming Leader. State: Replica: 9413960c10be47ebb2a54b5939ec0de9, State: Running, Role: LEADER
I20260812 06:19:51.556471 11188 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:51.556510 11193 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [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: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER }
I20260812 06:19:51.556921 11200 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9413960c10be47ebb2a54b5939ec0de9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER } }
I20260812 06:19:51.556946 11201 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9413960c10be47ebb2a54b5939ec0de9. Latest consensus state: current_term: 1 leader_uuid: "9413960c10be47ebb2a54b5939ec0de9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9413960c10be47ebb2a54b5939ec0de9" member_type: VOTER } }
I20260812 06:19:51.557107 11201 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.557343 11200 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:51.558174 11210 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:51.558179 10684 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:51.558828 11210 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:51.560527 11210 catalog_manager.cc:1383] Generated new cluster ID: dc02b7a2958b42d8ae5bcf722434e937
I20260812 06:19:51.560577 11210 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:51.566593 11210 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:51.567080 11210 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:51.572980 11210 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9: Generated new TSK 0
I20260812 06:19:51.573108 11210 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:51.574168 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.575974 11233 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:51.576090 11229 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:51.576095 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:51.576040 11230 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:51.576339 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.576381 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:51.576401 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515591576401 us; error 0 us; skew 500 ppm
I20260812 06:19:51.577173 10684 webserver.cc:533] Webserver started at http://127.10.111.1:46377/ using document root <none> and password file <none>
I20260812 06:19:51.577337 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.577386 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.577458 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.577800 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/instance:
uuid: "f67612a8400e4d738c85f88202f0adfa"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-q9h9"
I20260812 06:19:51.579260 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:51.580174 11242 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.580412 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:51.580484 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root
uuid: "f67612a8400e4d738c85f88202f0adfa"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-q9h9"
I20260812 06:19:51.580554 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:51.588629 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.588917 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.589164 10684 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:51.589576 10684 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:51.589613 10684 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.589653 10684 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:51.589680 10684 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.593523 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.1:42489
I20260812 06:19:51.593549 11373 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.1:42489 every 8 connection(s)
I20260812 06:19:51.601786 11375 heartbeater.cc:344] Connected to a master server at 127.10.111.62:35787
I20260812 06:19:51.601874 11375 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:51.602077 11375 heartbeater.cc:507] Master 127.10.111.62:35787 requested a full tablet report, sending...
I20260812 06:19:51.602630 11115 ts_manager.cc:194] Registered new tserver with Master: f67612a8400e4d738c85f88202f0adfa (127.10.111.1:42489)
I20260812 06:19:51.603276 11115 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52970
I20260812 06:19:51.603693 10684 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009783285s
I20260812 06:19:51.609676 11115 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52978:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:51.617452 11286 tablet_service.cc:1511] Processing CreateTablet for tablet 466d6ee140d04be4aedcdebe36f363ea (DEFAULT_TABLE table=heavy-update-compaction-test [id=fd1fe1c679514925b56f731d5e8be66f]), partition=
I20260812 06:19:51.617677 11286 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 466d6ee140d04be4aedcdebe36f363ea. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:51.619513 11397 tablet_bootstrap.cc:492] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Bootstrap starting.
I20260812 06:19:51.620376 11397 tablet_bootstrap.cc:654] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.621305 11397 tablet_bootstrap.cc:492] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: No bootstrap required, opened a new log
I20260812 06:19:51.621377 11397 ts_tablet_manager.cc:1403] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:51.621727 11397 raft_consensus.cc:359] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f67612a8400e4d738c85f88202f0adfa" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 42489 } }
I20260812 06:19:51.621807 11397 raft_consensus.cc:385] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.621834 11397 raft_consensus.cc:740] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f67612a8400e4d738c85f88202f0adfa, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.621927 11397 consensus_queue.cc:260] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [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: "f67612a8400e4d738c85f88202f0adfa" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 42489 } }
I20260812 06:19:51.621982 11397 raft_consensus.cc:399] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.622009 11397 raft_consensus.cc:493] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.622081 11397 raft_consensus.cc:3060] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.622772 11397 raft_consensus.cc:515] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f67612a8400e4d738c85f88202f0adfa" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 42489 } }
I20260812 06:19:51.622917 11397 leader_election.cc:304] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [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: f67612a8400e4d738c85f88202f0adfa; no voters: 
I20260812 06:19:51.623107 11397 leader_election.cc:290] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.623210 11400 raft_consensus.cc:2804] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.623392 11400 raft_consensus.cc:697] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 1 LEADER]: Becoming Leader. State: Replica: f67612a8400e4d738c85f88202f0adfa, State: Running, Role: LEADER
I20260812 06:19:51.623425 11397 ts_tablet_manager.cc:1434] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:51.623481 11375 heartbeater.cc:499] Master 127.10.111.62:35787 was elected leader, sending a full tablet report...
I20260812 06:19:51.623620 11400 consensus_queue.cc:237] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [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: "f67612a8400e4d738c85f88202f0adfa" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 42489 } }
I20260812 06:19:51.624809 11115 catalog_manager.cc:5719] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa reported cstate change: term changed from 0 to 1, leader changed from <none> to f67612a8400e4d738c85f88202f0adfa (127.10.111.1). New cstate: current_term: 1 leader_uuid: "f67612a8400e4d738c85f88202f0adfa" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f67612a8400e4d738c85f88202f0adfa" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 42489 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:51.679188 10684 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.017s	sys 0.006s
I20260812 06:19:51.844429 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea): perf score=23.023690
I20260812 06:19:52.000548 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.156s	user 0.094s	sys 0.056s Metrics: {"bytes_written":13086952,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":873,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40793,"lbm_writes_lt_1ms":876,"mutex_wait_us":898,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":16384,"update_count":1595}
I20260812 06:19:52.001221 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 20743880 bytes of WAL
I20260812 06:19:52.001473 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 2 log segments from log reader
I20260812 06:19:52.001526 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000001 (ops 1-6)
I20260812 06:19:52.001566 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000002 (ops 7-11)
I20260812 06:19:52.005240 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:52.005540 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea): 20513813 bytes on disk
I20260812 06:19:52.005964 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea) 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:19:52.006405 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.033097 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.027s	user 0.016s	sys 0.006s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":5471,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:52.033447 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.046329 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4953,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.046720 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:52.239602 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.193s	user 0.124s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815786,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":514,"lbm_read_time_us":13587,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33209,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":317,"threads_started":5,"update_count":2500}
I20260812 06:19:52.240197 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:52.294461 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.054s	user 0.042s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24568,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.294943 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.306187 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.306694 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:52.492017 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.185s	user 0.119s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":13205,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:19:52.492825 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:52.540185 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.046s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20684,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.540594 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.552211 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.552712 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:52.709031 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.156s	user 0.111s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1041,"lbm_read_time_us":9780,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28541,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.709549 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:52.751778 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.042s	user 0.016s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16678,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.752281 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.767385 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.767853 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:52.912690 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.145s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":834,"lbm_read_time_us":10034,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29585,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35840,"update_count":2500}
I20260812 06:19:52.913309 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=10.126437
I20260812 06:19:52.942276 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.029s	user 0.013s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.942677 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:52.954975 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.955559 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:53.076097 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.120s	user 0.092s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":8356,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24246,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":111744,"update_count":2000}
I20260812 06:19:53.076637 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=10.126437
I20260812 06:19:53.120735 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.044s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":19453,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:53.121215 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:53.130744 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.131191 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:53.160887 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.029s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1102,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2064,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:53.161463 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 112239265 bytes of WAL
I20260812 06:19:53.161677 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 11 log segments from log reader
I20260812 06:19:53.161726 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000003 (ops 12-16)
I20260812 06:19:53.161755 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000004 (ops 17-21)
I20260812 06:19:53.161785 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000005 (ops 22-26)
I20260812 06:19:53.161818 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000006 (ops 27-31)
I20260812 06:19:53.161842 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000007 (ops 32-36)
I20260812 06:19:53.161873 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000008 (ops 37-41)
I20260812 06:19:53.161906 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000009 (ops 42-46)
I20260812 06:19:53.161936 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000010 (ops 47-50)
I20260812 06:19:53.161967 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000011 (ops 51-55)
I20260812 06:19:53.161998 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000012 (ops 56-60)
I20260812 06:19:53.162096 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000013 (ops 61-65)
I20260812 06:19:53.182303 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.021s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:19:53.182716 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=3.181125
I20260812 06:19:53.208158 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.025s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6617,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.208601 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 12017983 bytes of WAL
I20260812 06:19:53.208810 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 1 log segments from log reader
I20260812 06:19:53.208863 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000014 (ops 66-70)
I20260812 06:19:53.210901 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:53.211212 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea): 447 bytes on disk
I20260812 06:19:53.211607 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.212055 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:53.221652 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3165,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.222162 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:53.391496 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.169s	user 0.112s	sys 0.057s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":975,"lbm_read_time_us":12705,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32863,"lbm_writes_lt_1ms":643,"mutex_wait_us":311,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:19:53.391990 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:53.435322 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.043s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18885,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.435835 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:53.451015 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.451433 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:53.614748 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.163s	user 0.119s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":12524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28887,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":2500}
I20260812 06:19:53.615329 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:53.682807 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.067s	user 0.024s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26476,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.683269 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:53.693249 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.693743 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:53.861169 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.167s	user 0.105s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":961,"lbm_read_time_us":13039,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29133,"lbm_writes_lt_1ms":543,"mutex_wait_us":357,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":60672,"update_count":2500}
I20260812 06:19:53.861698 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:53.923326 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.061s	user 0.028s	sys 0.026s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.923789 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:53.933414 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.933796 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:54.107203 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.173s	user 0.110s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":13712,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28913,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:19:54.107666 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:54.160844 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.053s	user 0.019s	sys 0.029s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18531,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.161327 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:54.171049 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.171437 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:54.352115 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.181s	user 0.119s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":803,"lbm_read_time_us":13415,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28898,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":94720,"update_count":2500}
I20260812 06:19:54.352617 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:54.398716 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.046s	user 0.023s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18939,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.399236 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:54.420430 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.021s	user 0.005s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.420866 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:54.601572 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.181s	user 0.140s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":950,"lbm_read_time_us":12794,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28398,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:54.602175 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:54.651918 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.050s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22316,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.652472 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:54.663918 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.664520 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:54.697042 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":989,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1870,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:54.697633 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 121006436 bytes of WAL
I20260812 06:19:54.697849 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 12 log segments from log reader
I20260812 06:19:54.697896 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000015 (ops 71-75)
I20260812 06:19:54.697924 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000016 (ops 76-80)
I20260812 06:19:54.697955 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000017 (ops 81-85)
I20260812 06:19:54.697988 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000018 (ops 86-90)
I20260812 06:19:54.698037 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000019 (ops 91-95)
I20260812 06:19:54.698072 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000020 (ops 96-100)
I20260812 06:19:54.698093 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000021 (ops 101-105)
I20260812 06:19:54.698125 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000022 (ops 106-110)
I20260812 06:19:54.698158 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000023 (ops 111-115)
I20260812 06:19:54.698189 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000024 (ops 116-120)
I20260812 06:19:54.698221 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000025 (ops 121-124)
I20260812 06:19:54.698253 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000026 (ops 125-129)
I20260812 06:19:54.719753 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:54.720126 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea): 492 bytes on disk
I20260812 06:19:54.720504 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.720991 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=3.181125
I20260812 06:19:54.743088 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.022s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.743500 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 12017954 bytes of WAL
I20260812 06:19:54.743701 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 1 log segments from log reader
I20260812 06:19:54.743746 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000027 (ops 130-134)
I20260812 06:19:54.745692 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:54.745958 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:54.754452 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.008s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3176,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.754802 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:54.991971 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.237s	user 0.165s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020730,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1212,"lbm_read_time_us":15495,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39599,"lbm_writes_lt_1ms":743,"mutex_wait_us":318,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":99200,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:19:54.992930 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=18.063937
I20260812 06:19:55.068001 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.075s	user 0.030s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29364,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:55.068483 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:55.083756 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.084350 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:55.274086 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.189s	user 0.138s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":593,"lbm_read_time_us":13584,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32428,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":183040,"update_count":3000}
I20260812 06:19:55.274780 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=14.095187
I20260812 06:19:55.325259 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.050s	user 0.042s	sys 0.005s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22827,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.325840 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:55.347620 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.348197 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:55.513841 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.165s	user 0.121s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":11026,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29364,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:19:55.514602 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=15.087375
I20260812 06:19:55.557296 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.042s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18399,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:55.557787 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:55.580214 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.022s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.580647 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:55.590269 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.590632 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:55.777601 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.187s	user 0.125s	sys 0.057s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2174,"lbm_read_time_us":13512,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31187,"lbm_writes_lt_1ms":643,"mutex_wait_us":521,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:19:55.778220 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=16.079562
I20260812 06:19:55.824579 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.046s	user 0.023s	sys 0.021s Metrics: {"bytes_written":17968821,"delete_count":0,"lbm_write_time_us":20578,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:19:55.825078 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.196750
I20260812 06:19:55.840197 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.015s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2953959,"delete_count":0,"lbm_write_time_us":2915,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:55.840643 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:55.849442 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3459,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:55.849877 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:56.053651 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.204s	user 0.119s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918180,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":186,"lbm_read_time_us":13920,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33100,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":103040,"update_count":3000}
I20260812 06:19:56.055214 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=16.079562
I20260812 06:19:56.104413 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":18543157,"delete_count":0,"lbm_write_time_us":20944,"lbm_writes_lt_1ms":455,"reinsert_count":0,"update_count":2260}
I20260812 06:19:56.105015 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.196750
I20260812 06:19:56.119088 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2379608,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:19:56.119516 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:56.128376 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3551,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.128763 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:56.157972 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushMRSOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.029s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":930,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1384,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:56.158713 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling LogGCOp(466d6ee140d04be4aedcdebe36f363ea): free 121459768 bytes of WAL
I20260812 06:19:56.158947 11252 log_reader.cc:385] T 466d6ee140d04be4aedcdebe36f363ea: removed 12 log segments from log reader
I20260812 06:19:56.159004 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000028 (ops 135-139)
I20260812 06:19:56.159050 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000029 (ops 140-144)
I20260812 06:19:56.159085 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000030 (ops 145-149)
I20260812 06:19:56.159116 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000031 (ops 150-154)
I20260812 06:19:56.159154 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000032 (ops 155-159)
I20260812 06:19:56.159188 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000033 (ops 160-164)
I20260812 06:19:56.159219 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000034 (ops 165-169)
I20260812 06:19:56.159248 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000035 (ops 170-174)
I20260812 06:19:56.159287 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000036 (ops 175-179)
I20260812 06:19:56.159317 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000037 (ops 180-184)
I20260812 06:19:56.159349 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000038 (ops 185-189)
I20260812 06:19:56.159379 11252 log.cc:1079] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: Deleting log segment in path: /tmp/dist-test-task5aYmmc/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515586373690-10684-0/minicluster-data/ts-0-root/wals/466d6ee140d04be4aedcdebe36f363ea/wal-000000039 (ops 190-194)
I20260812 06:19:56.187364 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: LogGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:56.187726 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=3.181125
I20260812 06:19:56.202379 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4019,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.202839 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea): perf score=2.188937
I20260812 06:19:56.211758 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: FlushDeltaMemStoresOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3349,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.212195 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea): 482 bytes on disk
I20260812 06:19:56.212579 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: UndoDeltaBlockGCOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.213091 11380 maintenance_manager.cc:419] P f67612a8400e4d738c85f88202f0adfa: Scheduling MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea): perf score=1.000000
I20260812 06:19:56.289089 10684 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.610s	user 1.637s	sys 0.201s
I20260812 06:19:56.390383 10684 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.101s	user 0.004s	sys 0.000s
I20260812 06:19:56.390924 10684 tablet_server.cc:179] TabletServer@127.10.111.1:0 shutting down...
I20260812 06:19:56.426200 11252 maintenance_manager.cc:643] P f67612a8400e4d738c85f88202f0adfa: MajorDeltaCompactionOp(466d6ee140d04be4aedcdebe36f363ea) complete. Timing: real 0.213s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123213,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":5194,"lbm_read_time_us":15834,"lbm_reads_lt_1ms":871,"lbm_write_time_us":34160,"lbm_writes_lt_1ms":843,"mutex_wait_us":2307,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":68,"threads_started":1,"update_count":4000}
I20260812 06:19:56.426674 10684 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:56.426908 10684 tablet_replica.cc:333] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa: stopping tablet replica
I20260812 06:19:56.427038 10684 raft_consensus.cc:2243] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.427191 10684 raft_consensus.cc:2272] T 466d6ee140d04be4aedcdebe36f363ea P f67612a8400e4d738c85f88202f0adfa [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.431243 10684 tablet_server.cc:196] TabletServer@127.10.111.1:0 shutdown complete.
I20260812 06:19:56.494632 10684 master.cc:562] Master@127.10.111.62:35787 shutting down...
I20260812 06:19:56.497496 10684 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.497649 10684 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.497716 10684 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9413960c10be47ebb2a54b5939ec0de9: stopping tablet replica
I20260812 06:19:56.509709 10684 master.cc:584] Master@127.10.111.62:35787 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5084 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10199 ms total)

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