[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:56.024806 16559 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.43.254:37871
I20260812 06:17:56.025920 16559 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:56.026728 16559 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:56.033543 16571 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:56.033571 16568 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:56.033833 16559 server_base.cc:1061] running on GCE node
W20260812 06:17:56.033847 16567 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:56.034549 16559 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:56.034673 16559 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:56.034719 16559 hybrid_clock.cc:648] HybridClock initialized: now 1786515476034717 us; error 0 us; skew 500 ppm
I20260812 06:17:56.037294 16559 webserver.cc:533] Webserver started at http://127.16.43.254:34831/ using document root <none> and password file <none>
I20260812 06:17:56.038072 16559 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:56.038177 16559 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:56.038434 16559 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:56.040275 16559 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/master-0-root/instance:
uuid: "2e78500c7106422a999a4e66712993ef"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-c12x"
I20260812 06:17:56.044219 16559 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:17:56.046648 16576 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.048007 16559 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:56.048146 16559 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/master-0-root
uuid: "2e78500c7106422a999a4e66712993ef"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-c12x"
I20260812 06:17:56.048262 16559 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:56.064047 16559 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:56.064759 16559 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:56.064963 16559 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:56.074317 16559 rpc_server.cc:307] RPC server started. Bound to: 127.16.43.254:37871
I20260812 06:17:56.074345 16669 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.43.254:37871 every 8 connection(s)
I20260812 06:17:56.076890 16671 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:56.082623 16671 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: Bootstrap starting.
I20260812 06:17:56.085168 16671 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:56.086130 16671 log.cc:826] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:56.088033 16671 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: No bootstrap required, opened a new log
I20260812 06:17:56.091012 16671 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e78500c7106422a999a4e66712993ef" member_type: VOTER }
I20260812 06:17:56.091183 16671 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:56.091260 16671 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2e78500c7106422a999a4e66712993ef, State: Initialized, Role: FOLLOWER
I20260812 06:17:56.092011 16671 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [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: "2e78500c7106422a999a4e66712993ef" member_type: VOTER }
I20260812 06:17:56.092177 16671 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:56.092299 16671 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:56.092448 16671 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:56.093366 16671 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e78500c7106422a999a4e66712993ef" member_type: VOTER }
I20260812 06:17:56.093868 16671 leader_election.cc:304] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [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: 2e78500c7106422a999a4e66712993ef; no voters: 
I20260812 06:17:56.094235 16671 leader_election.cc:290] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:56.094396 16678 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:56.094666 16678 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 1 LEADER]: Becoming Leader. State: Replica: 2e78500c7106422a999a4e66712993ef, State: Running, Role: LEADER
I20260812 06:17:56.095170 16678 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [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: "2e78500c7106422a999a4e66712993ef" member_type: VOTER }
I20260812 06:17:56.095290 16671 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:56.097589 16680 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2e78500c7106422a999a4e66712993ef. Latest consensus state: current_term: 1 leader_uuid: "2e78500c7106422a999a4e66712993ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e78500c7106422a999a4e66712993ef" member_type: VOTER } }
I20260812 06:17:56.097671 16559 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:56.097711 16680 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:56.097772 16679 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2e78500c7106422a999a4e66712993ef" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2e78500c7106422a999a4e66712993ef" member_type: VOTER } }
I20260812 06:17:56.097838 16679 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [sys.catalog]: This master's current role is: LEADER
W20260812 06:17:56.099972 16700 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:56.100056 16700 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:56.100158 16701 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:56.100948 16701 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:56.106256 16701 catalog_manager.cc:1383] Generated new cluster ID: 8b7b7d55a8434c47a5f52e5e1b067bc4
I20260812 06:17:56.106343 16701 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:56.112937 16701 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:56.114152 16701 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:56.132992 16701 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: Generated new TSK 0
I20260812 06:17:56.133920 16701 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:56.162755 16559 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:56.165717 16709 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:17:56.165779 16712 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:56.165843 16714 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:56.166551 16559 server_base.cc:1061] running on GCE node
I20260812 06:17:56.166726 16559 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:56.166772 16559 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:56.166795 16559 hybrid_clock.cc:648] HybridClock initialized: now 1786515476166794 us; error 0 us; skew 500 ppm
I20260812 06:17:56.167771 16559 webserver.cc:533] Webserver started at http://127.16.43.193:37501/ using document root <none> and password file <none>
I20260812 06:17:56.167939 16559 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:56.168008 16559 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:56.168094 16559 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:56.168534 16559 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/instance:
uuid: "5a6a8a0d5c9e458ca801592da10a4fb6"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-c12x"
I20260812 06:17:56.170418 16559 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:56.171617 16722 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.171947 16559 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:56.172021 16559 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root
uuid: "5a6a8a0d5c9e458ca801592da10a4fb6"
format_stamp: "Formatted at 2026-08-12 06:17:56 on dist-test-slave-c12x"
I20260812 06:17:56.172122 16559 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:56.182008 16559 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:56.182488 16559 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:56.183068 16559 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:56.184115 16559 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:56.184173 16559 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.184244 16559 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:56.184296 16559 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:56.192014 16559 rpc_server.cc:307] RPC server started. Bound to: 127.16.43.193:40553
I20260812 06:17:56.192039 16837 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.43.193:40553 every 8 connection(s)
I20260812 06:17:56.207152 16839 heartbeater.cc:344] Connected to a master server at 127.16.43.254:37871
I20260812 06:17:56.207504 16839 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:56.208024 16839 heartbeater.cc:507] Master 127.16.43.254:37871 requested a full tablet report, sending...
I20260812 06:17:56.209527 16601 ts_manager.cc:194] Registered new tserver with Master: 5a6a8a0d5c9e458ca801592da10a4fb6 (127.16.43.193:40553)
I20260812 06:17:56.209897 16559 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017187103s
I20260812 06:17:56.211071 16601 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48428
I20260812 06:17:56.220854 16601 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48440:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:56.237313 16767 tablet_service.cc:1511] Processing CreateTablet for tablet 9ebfaa67f9734468a71676c7eb37450f (DEFAULT_TABLE table=heavy-update-compaction-test [id=a1dee7f78924488ab8afb3cfcc5e7e9d]), partition=
I20260812 06:17:56.237936 16767 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9ebfaa67f9734468a71676c7eb37450f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:56.241159 16856 tablet_bootstrap.cc:492] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Bootstrap starting.
I20260812 06:17:56.242255 16856 tablet_bootstrap.cc:654] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:56.243592 16856 tablet_bootstrap.cc:492] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: No bootstrap required, opened a new log
I20260812 06:17:56.243713 16856 ts_tablet_manager.cc:1403] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:56.244218 16856 raft_consensus.cc:359] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a6a8a0d5c9e458ca801592da10a4fb6" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 40553 } }
I20260812 06:17:56.244330 16856 raft_consensus.cc:385] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:56.244380 16856 raft_consensus.cc:740] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5a6a8a0d5c9e458ca801592da10a4fb6, State: Initialized, Role: FOLLOWER
I20260812 06:17:56.244628 16856 consensus_queue.cc:260] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [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: "5a6a8a0d5c9e458ca801592da10a4fb6" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 40553 } }
I20260812 06:17:56.244762 16856 raft_consensus.cc:399] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:56.244834 16856 raft_consensus.cc:493] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:56.244884 16856 raft_consensus.cc:3060] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:56.245817 16856 raft_consensus.cc:515] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a6a8a0d5c9e458ca801592da10a4fb6" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 40553 } }
I20260812 06:17:56.246001 16856 leader_election.cc:304] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [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: 5a6a8a0d5c9e458ca801592da10a4fb6; no voters: 
I20260812 06:17:56.246276 16856 leader_election.cc:290] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:56.246429 16858 raft_consensus.cc:2804] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:56.246651 16858 raft_consensus.cc:697] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 1 LEADER]: Becoming Leader. State: Replica: 5a6a8a0d5c9e458ca801592da10a4fb6, State: Running, Role: LEADER
I20260812 06:17:56.246811 16858 consensus_queue.cc:237] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [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: "5a6a8a0d5c9e458ca801592da10a4fb6" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 40553 } }
I20260812 06:17:56.246909 16856 ts_tablet_manager.cc:1434] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:56.246963 16839 heartbeater.cc:499] Master 127.16.43.254:37871 was elected leader, sending a full tablet report...
I20260812 06:17:56.250098 16601 catalog_manager.cc:5719] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5a6a8a0d5c9e458ca801592da10a4fb6 (127.16.43.193). New cstate: current_term: 1 leader_uuid: "5a6a8a0d5c9e458ca801592da10a4fb6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5a6a8a0d5c9e458ca801592da10a4fb6" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 40553 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:56.328548 16559 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.069s	user 0.020s	sys 0.014s
I20260812 06:17:56.443245 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f): perf score=15.086190
I20260812 06:17:56.593077 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.149s	user 0.104s	sys 0.036s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":219,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":757,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34354,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":556,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":141,"threads_started":1,"update_count":1000}
I20260812 06:17:56.594219 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling LogGCOp(9ebfaa67f9734468a71676c7eb37450f): free 11976772 bytes of WAL
I20260812 06:17:56.594558 16729 log_reader.cc:385] T 9ebfaa67f9734468a71676c7eb37450f: removed 1 log segments from log reader
I20260812 06:17:56.594645 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000001 (ops 1-6)
I20260812 06:17:56.597951 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: LogGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:56.598306 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:56.611306 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.611936 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:56.723901 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.112s	user 0.091s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":725,"lbm_read_time_us":6695,"lbm_reads_lt_1ms":364,"lbm_write_time_us":19278,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":382,"threads_started":5,"update_count":1500}
I20260812 06:17:56.724489 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f): 12308958 bytes on disk
I20260812 06:17:56.725100 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:56.725646 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=6.157687
I20260812 06:17:56.763908 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.038s	user 0.017s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10185,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:56.764402 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:56.775017 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:56.775544 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:56.892107 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.116s	user 0.093s	sys 0.017s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528899,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":845,"lbm_read_time_us":7678,"lbm_reads_lt_1ms":372,"lbm_write_time_us":20562,"lbm_writes_lt_1ms":343,"mutex_wait_us":206,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:56.892768 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=7.149875
I20260812 06:17:56.919706 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.027s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11448,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:56.920174 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:56.931223 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3777,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:56.931792 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.047391 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.115s	user 0.087s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":6876,"lbm_reads_lt_1ms":372,"lbm_write_time_us":22290,"lbm_writes_lt_1ms":343,"mutex_wait_us":2,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":1500}
I20260812 06:17:57.048117 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=7.149875
I20260812 06:17:57.075021 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.027s	user 0.009s	sys 0.015s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":11370,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:57.075601 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:57.092413 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.017s	user 0.006s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:57.093014 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.222945 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.130s	user 0.090s	sys 0.029s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528892,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":887,"lbm_read_time_us":7996,"lbm_reads_lt_1ms":364,"lbm_write_time_us":21273,"lbm_writes_lt_1ms":343,"mutex_wait_us":275,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":1500}
I20260812 06:17:57.223503 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=10.126437
I20260812 06:17:57.276518 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.053s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.277112 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:57.289197 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.289901 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.422000 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.132s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1535,"lbm_read_time_us":7833,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25396,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:17:57.422510 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=10.126437
I20260812 06:17:57.469578 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.047s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14754,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.470196 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:57.484877 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.014s	user 0.003s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.485464 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.634069 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.148s	user 0.133s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":119,"lbm_read_time_us":10474,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28025,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:57.634727 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=10.126437
I20260812 06:17:57.677779 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.043s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16311,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.678344 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:57.695163 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.695945 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.839653 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.143s	user 0.110s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1311,"lbm_read_time_us":10501,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31907,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":131,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:17:57.840595 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=10.126437
I20260812 06:17:57.884421 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.044s	user 0.009s	sys 0.031s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14935,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:57.884954 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:57.895810 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:57.896309 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:57.931137 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.035s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1762,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1390,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:57.932273 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:58.092408 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.160s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":560,"lbm_read_time_us":11122,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26963,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:17:58.093111 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling LogGCOp(9ebfaa67f9734468a71676c7eb37450f): free 121006426 bytes of WAL
I20260812 06:17:58.093401 16729 log_reader.cc:385] T 9ebfaa67f9734468a71676c7eb37450f: removed 12 log segments from log reader
I20260812 06:17:58.093467 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000002 (ops 7-11)
I20260812 06:17:58.093523 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000003 (ops 12-16)
I20260812 06:17:58.093566 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000004 (ops 17-20)
I20260812 06:17:58.093611 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000005 (ops 21-25)
I20260812 06:17:58.093642 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000006 (ops 26-30)
I20260812 06:17:58.093683 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000007 (ops 31-35)
I20260812 06:17:58.093725 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000008 (ops 36-40)
I20260812 06:17:58.093770 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000009 (ops 41-45)
I20260812 06:17:58.093807 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000010 (ops 46-50)
I20260812 06:17:58.093858 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000011 (ops 51-55)
I20260812 06:17:58.093899 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000012 (ops 56-60)
I20260812 06:17:58.093940 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000013 (ops 61-65)
I20260812 06:17:58.124643 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: LogGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:58.125209 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:17:58.171952 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.047s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21276,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.172495 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:58.189843 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.190372 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f): 448 bytes on disk
I20260812 06:17:58.190887 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:58.191469 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:58.347718 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.156s	user 0.127s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1651,"lbm_read_time_us":11403,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31124,"lbm_writes_lt_1ms":543,"mutex_wait_us":439,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:17:58.348448 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=11.118625
I20260812 06:17:58.400585 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.052s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20358,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:17:58.401032 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:58.412822 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.413327 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:58.423869 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3803,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:58.424312 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:58.595592 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.171s	user 0.136s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1874,"lbm_read_time_us":11818,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32722,"lbm_writes_lt_1ms":543,"mutex_wait_us":725,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:58.596256 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:17:58.661171 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.065s	user 0.050s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":29401,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.661753 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:58.677503 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.678256 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:58.851868 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.173s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":349,"lbm_read_time_us":11495,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35673,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:58.852546 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:17:58.912423 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.060s	user 0.034s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:58.912966 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:58.927145 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:58.927809 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:59.088830 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.160s	user 0.117s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":791,"lbm_read_time_us":9684,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31479,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:17:59.089550 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:17:59.146797 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.057s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23475,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.147377 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:59.159260 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.159989 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:59.341769 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.182s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":11939,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31309,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":144896,"update_count":2500}
I20260812 06:17:59.342729 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:17:59.411182 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.068s	user 0.015s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24748,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:59.411870 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:59.423727 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.424465 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:59.459616 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.035s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1281,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2182,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:59.460364 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling LogGCOp(9ebfaa67f9734468a71676c7eb37450f): free 120553382 bytes of WAL
I20260812 06:17:59.460703 16729 log_reader.cc:385] T 9ebfaa67f9734468a71676c7eb37450f: removed 12 log segments from log reader
I20260812 06:17:59.460774 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000014 (ops 66-70)
I20260812 06:17:59.460809 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000015 (ops 71-75)
I20260812 06:17:59.460835 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000016 (ops 76-80)
I20260812 06:17:59.460862 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000017 (ops 81-84)
I20260812 06:17:59.460886 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000018 (ops 85-89)
I20260812 06:17:59.460916 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000019 (ops 90-94)
I20260812 06:17:59.460947 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000020 (ops 95-99)
I20260812 06:17:59.460973 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000021 (ops 100-104)
I20260812 06:17:59.461019 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000022 (ops 105-109)
I20260812 06:17:59.461045 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000023 (ops 110-114)
I20260812 06:17:59.461074 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000024 (ops 115-118)
I20260812 06:17:59.461102 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000025 (ops 119-123)
I20260812 06:17:59.490197 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: LogGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:59.490732 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f): 472 bytes on disk
I20260812 06:17:59.491245 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:59.491851 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:59.514842 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.023s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.515316 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:17:59.532243 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.532904 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:17:59.756079 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.223s	user 0.159s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938787,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":715,"lbm_read_time_us":16509,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38464,"lbm_writes_lt_1ms":743,"mutex_wait_us":328,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:17:59.756683 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=15.087375
I20260812 06:17:59.822054 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.065s	user 0.016s	sys 0.033s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22824,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:59.822574 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=6.157687
I20260812 06:17:59.849231 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.026s	user 0.006s	sys 0.013s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":8593,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:59.849809 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:00.020511 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.171s	user 0.138s	sys 0.033s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836136,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1184,"lbm_read_time_us":13081,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34609,"lbm_writes_lt_1ms":643,"mutex_wait_us":276,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":3000}
I20260812 06:18:00.021291 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:18:00.070255 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.049s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21418,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.070876 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.088259 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.088999 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:00.237478 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.148s	user 0.095s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":919,"lbm_read_time_us":8848,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27866,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:00.238149 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:18:00.303754 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.065s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25698,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.304352 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.315747 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.316452 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:00.496843 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.180s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":12478,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32710,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:18:00.497655 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:18:00.559554 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.062s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20179,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.560060 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.571272 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.571938 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:00.755249 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.183s	user 0.110s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":13148,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31189,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:00.755864 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=14.095187
I20260812 06:18:00.820498 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.064s	user 0.039s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21372,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:00.821070 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.832188 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.832744 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:00.872963 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushMRSOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.040s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1442,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:00.873771 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling LogGCOp(9ebfaa67f9734468a71676c7eb37450f): free 112239478 bytes of WAL
I20260812 06:18:00.874234 16729 log_reader.cc:385] T 9ebfaa67f9734468a71676c7eb37450f: removed 11 log segments from log reader
I20260812 06:18:00.874311 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000026 (ops 124-128)
I20260812 06:18:00.874353 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000027 (ops 129-133)
I20260812 06:18:00.874378 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000028 (ops 134-138)
I20260812 06:18:00.874588 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000029 (ops 139-142)
I20260812 06:18:00.874629 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000030 (ops 143-147)
I20260812 06:18:00.874653 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000031 (ops 148-152)
I20260812 06:18:00.874678 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000032 (ops 153-157)
I20260812 06:18:00.874702 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000033 (ops 158-162)
I20260812 06:18:00.874727 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000034 (ops 163-167)
I20260812 06:18:00.874751 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000035 (ops 168-172)
I20260812 06:18:00.874786 16729 log.cc:1079] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ebfaa67f9734468a71676c7eb37450f/wal-000000036 (ops 173-177)
I20260812 06:18:00.904829 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: LogGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:00.905315 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.930321 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.025s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.930776 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f): 446 bytes on disk
I20260812 06:18:00.931182 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: UndoDeltaBlockGCOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.931743 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:00.942018 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.942819 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:01.168454 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.225s	user 0.160s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938785,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":834,"lbm_read_time_us":13303,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36935,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":64,"threads_started":1,"update_count":3500}
I20260812 06:18:01.169054 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=18.063937
I20260812 06:18:01.231081 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.062s	user 0.036s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28312,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:01.232091 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=2.188937
I20260812 06:18:01.245770 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.246304 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f): perf score=1.000000
I20260812 06:18:01.375376 16559 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.047s	user 1.870s	sys 0.178s
I20260812 06:18:01.418397 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: MajorDeltaCompactionOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.172s	user 0.110s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":12212,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34913,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:01.418895 16841 maintenance_manager.cc:419] P 5a6a8a0d5c9e458ca801592da10a4fb6: Scheduling FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f): perf score=10.126437
I20260812 06:18:01.435598 16559 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.060s	user 0.004s	sys 0.000s
I20260812 06:18:01.436264 16559 tablet_server.cc:179] TabletServer@127.16.43.193:0 shutting down...
I20260812 06:18:01.455741 16729 maintenance_manager.cc:643] P 5a6a8a0d5c9e458ca801592da10a4fb6: FlushDeltaMemStoresOp(9ebfaa67f9734468a71676c7eb37450f) complete. Timing: real 0.037s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15590,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.456400 16559 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:01.456856 16559 tablet_replica.cc:333] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6: stopping tablet replica
I20260812 06:18:01.457108 16559 raft_consensus.cc:2243] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:01.457350 16559 raft_consensus.cc:2272] T 9ebfaa67f9734468a71676c7eb37450f P 5a6a8a0d5c9e458ca801592da10a4fb6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:01.476205 16559 tablet_server.cc:196] TabletServer@127.16.43.193:0 shutdown complete.
I20260812 06:18:01.481019 16559 master.cc:562] Master@127.16.43.254:37871 shutting down...
I20260812 06:18:01.484959 16559 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:01.485118 16559 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:01.485173 16559 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2e78500c7106422a999a4e66712993ef: stopping tablet replica
I20260812 06:18:01.497826 16559 master.cc:584] Master@127.16.43.254:37871 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5570 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:01.594345 16559 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.43.254:36677
I20260812 06:18:01.594753 16559 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:01.597383 16559 server_base.cc:1061] running on GCE node
W20260812 06:18:01.597437 16884 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:01.597466 16887 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:01.597584 16883 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:01.597867 16559 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:01.597910 16559 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:01.597926 16559 hybrid_clock.cc:648] HybridClock initialized: now 1786515481597926 us; error 0 us; skew 500 ppm
I20260812 06:18:01.598784 16559 webserver.cc:533] Webserver started at http://127.16.43.254:34885/ using document root <none> and password file <none>
I20260812 06:18:01.598914 16559 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:01.598958 16559 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:01.599010 16559 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:01.599363 16559 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/master-0-root/instance:
uuid: "65ed31cbd25f42b7bf9a971387c30fd9"
format_stamp: "Formatted at 2026-08-12 06:18:01 on dist-test-slave-c12x"
I20260812 06:18:01.601097 16559 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:01.602017 16894 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:01.602344 16559 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:01.602411 16559 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/master-0-root
uuid: "65ed31cbd25f42b7bf9a971387c30fd9"
format_stamp: "Formatted at 2026-08-12 06:18:01 on dist-test-slave-c12x"
I20260812 06:18:01.602475 16559 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:01.616886 16559 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:01.617400 16559 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:01.623334 16559 rpc_server.cc:307] RPC server started. Bound to: 127.16.43.254:36677
I20260812 06:18:01.624136 16990 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.43.254:36677 every 8 connection(s)
I20260812 06:18:01.624939 16991 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:01.640563 16991 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9: Bootstrap starting.
I20260812 06:18:01.641623 16991 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:01.643165 16991 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9: No bootstrap required, opened a new log
I20260812 06:18:01.643779 16991 raft_consensus.cc:359] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER }
I20260812 06:18:01.643914 16991 raft_consensus.cc:385] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:01.643976 16991 raft_consensus.cc:740] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 65ed31cbd25f42b7bf9a971387c30fd9, State: Initialized, Role: FOLLOWER
I20260812 06:18:01.644127 16991 consensus_queue.cc:260] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [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: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER }
I20260812 06:18:01.644222 16991 raft_consensus.cc:399] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:01.644265 16991 raft_consensus.cc:493] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:01.644318 16991 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:01.645104 16991 raft_consensus.cc:515] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER }
I20260812 06:18:01.645257 16991 leader_election.cc:304] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [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: 65ed31cbd25f42b7bf9a971387c30fd9; no voters: 
I20260812 06:18:01.645481 16991 leader_election.cc:290] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:01.645656 16996 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:01.645881 16996 raft_consensus.cc:697] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 1 LEADER]: Becoming Leader. State: Replica: 65ed31cbd25f42b7bf9a971387c30fd9, State: Running, Role: LEADER
I20260812 06:18:01.646040 16996 consensus_queue.cc:237] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [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: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER }
I20260812 06:18:01.646077 16991 sys_catalog.cc:565] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:01.646682 16997 sys_catalog.cc:455] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 65ed31cbd25f42b7bf9a971387c30fd9. Latest consensus state: current_term: 1 leader_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER } }
I20260812 06:18:01.646770 16997 sys_catalog.cc:458] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:01.647030 16998 sys_catalog.cc:455] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65ed31cbd25f42b7bf9a971387c30fd9" member_type: VOTER } }
I20260812 06:18:01.647118 16998 sys_catalog.cc:458] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:01.647527 17002 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:01.648367 17002 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:01.648505 16559 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:01.650333 17002 catalog_manager.cc:1383] Generated new cluster ID: ce6e6a3a2f7343ccb03e9b7d834145a6
I20260812 06:18:01.650436 17002 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:01.660763 17002 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:01.661324 17002 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:01.667244 17002 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9: Generated new TSK 0
I20260812 06:18:01.667512 17002 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:01.681232 16559 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:01.683598 17020 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:01.683633 17022 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:01.683633 17030 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:01.683911 16559 server_base.cc:1061] running on GCE node
I20260812 06:18:01.684108 16559 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:01.684161 16559 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:01.684186 16559 hybrid_clock.cc:648] HybridClock initialized: now 1786515481684185 us; error 0 us; skew 500 ppm
I20260812 06:18:01.685261 16559 webserver.cc:533] Webserver started at http://127.16.43.193:34649/ using document root <none> and password file <none>
I20260812 06:18:01.685571 16559 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:01.685647 16559 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:01.685730 16559 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:01.686160 16559 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/instance:
uuid: "6916ec7d5394412bb60a330b5d5119b9"
format_stamp: "Formatted at 2026-08-12 06:18:01 on dist-test-slave-c12x"
I20260812 06:18:01.687804 16559 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:01.688876 17037 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:01.689206 16559 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:01.689298 16559 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root
uuid: "6916ec7d5394412bb60a330b5d5119b9"
format_stamp: "Formatted at 2026-08-12 06:18:01 on dist-test-slave-c12x"
I20260812 06:18:01.689383 16559 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:01.703316 16559 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:01.703796 16559 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:01.704125 16559 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:01.704612 16559 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:01.704676 16559 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:01.704730 16559 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:01.704777 16559 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:01.709316 16559 rpc_server.cc:307] RPC server started. Bound to: 127.16.43.193:34301
I20260812 06:18:01.709353 17135 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.43.193:34301 every 8 connection(s)
I20260812 06:18:01.718413 17136 heartbeater.cc:344] Connected to a master server at 127.16.43.254:36677
I20260812 06:18:01.718551 17136 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:01.718855 17136 heartbeater.cc:507] Master 127.16.43.254:36677 requested a full tablet report, sending...
I20260812 06:18:01.719604 16930 ts_manager.cc:194] Registered new tserver with Master: 6916ec7d5394412bb60a330b5d5119b9 (127.16.43.193:34301)
I20260812 06:18:01.719980 16559 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01021237s
I20260812 06:18:01.720436 16930 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49622
I20260812 06:18:01.727684 16930 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49630:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:01.736573 17081 tablet_service.cc:1511] Processing CreateTablet for tablet 9ec3b7c8874e4f8da01dc95e935faa7c (DEFAULT_TABLE table=heavy-update-compaction-test [id=924ab0ebde2e4a0982d219e302a7a422]), partition=
I20260812 06:18:01.736877 17081 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9ec3b7c8874e4f8da01dc95e935faa7c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:01.738850 17155 tablet_bootstrap.cc:492] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Bootstrap starting.
I20260812 06:18:01.739795 17155 tablet_bootstrap.cc:654] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:01.740901 17155 tablet_bootstrap.cc:492] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: No bootstrap required, opened a new log
I20260812 06:18:01.741014 17155 ts_tablet_manager.cc:1403] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:01.741425 17155 raft_consensus.cc:359] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6916ec7d5394412bb60a330b5d5119b9" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 34301 } }
I20260812 06:18:01.741537 17155 raft_consensus.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:01.741607 17155 raft_consensus.cc:740] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6916ec7d5394412bb60a330b5d5119b9, State: Initialized, Role: FOLLOWER
I20260812 06:18:01.741753 17155 consensus_queue.cc:260] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [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: "6916ec7d5394412bb60a330b5d5119b9" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 34301 } }
I20260812 06:18:01.741856 17155 raft_consensus.cc:399] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:01.741902 17155 raft_consensus.cc:493] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:01.741955 17155 raft_consensus.cc:3060] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:01.742766 17155 raft_consensus.cc:515] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6916ec7d5394412bb60a330b5d5119b9" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 34301 } }
I20260812 06:18:01.742919 17155 leader_election.cc:304] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [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: 6916ec7d5394412bb60a330b5d5119b9; no voters: 
I20260812 06:18:01.743122 17155 leader_election.cc:290] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:01.743256 17157 raft_consensus.cc:2804] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:01.743484 17155 ts_tablet_manager.cc:1434] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:01.743536 17157 raft_consensus.cc:697] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 1 LEADER]: Becoming Leader. State: Replica: 6916ec7d5394412bb60a330b5d5119b9, State: Running, Role: LEADER
I20260812 06:18:01.743549 17136 heartbeater.cc:499] Master 127.16.43.254:36677 was elected leader, sending a full tablet report...
I20260812 06:18:01.743703 17157 consensus_queue.cc:237] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [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: "6916ec7d5394412bb60a330b5d5119b9" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 34301 } }
I20260812 06:18:01.745055 16930 catalog_manager.cc:5719] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6916ec7d5394412bb60a330b5d5119b9 (127.16.43.193). New cstate: current_term: 1 leader_uuid: "6916ec7d5394412bb60a330b5d5119b9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6916ec7d5394412bb60a330b5d5119b9" member_type: VOTER last_known_addr { host: "127.16.43.193" port: 34301 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:01.806031 16559 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.019s	sys 0.004s
I20260812 06:18:01.960305 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=19.054940
I20260812 06:18:02.119246 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.159s	user 0.119s	sys 0.036s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":709,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41506,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:02.119928 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): free 20743880 bytes of WAL
I20260812 06:18:02.120184 17043 log_reader.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c: removed 2 log segments from log reader
I20260812 06:18:02.120250 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000001 (ops 1-6)
I20260812 06:18:02.120304 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000002 (ops 7-11)
I20260812 06:18:02.124740 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:02.125164 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:02.141472 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.016s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.142031 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:02.302083 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.160s	user 0.130s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26266,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":295,"threads_started":5,"update_count":2000}
I20260812 06:18:02.302645 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): 16411396 bytes on disk
I20260812 06:18:02.303092 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.303515 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:02.354389 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.051s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20244,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.354972 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:02.365911 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.366501 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:02.531345 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.165s	user 0.108s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":8558,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30653,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:18:02.532141 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:02.599838 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.068s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25214,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.600330 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:02.616571 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.617194 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:02.810628 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.193s	user 0.103s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":12105,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32875,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:02.811421 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:02.871306 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.060s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26785,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.871842 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:02.884547 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.885231 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:03.077605 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.192s	user 0.133s	sys 0.057s 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":155,"lbm_read_time_us":13122,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33063,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:03.079679 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:03.137187 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.057s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20386,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.137898 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:03.149415 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4663,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.150032 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:03.352176 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.202s	user 0.129s	sys 0.063s 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":309,"lbm_read_time_us":14219,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32081,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:18:03.352921 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:03.403690 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.051s	user 0.039s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20025,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.404157 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:03.426870 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.023s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.427716 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:03.464804 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.037s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1362,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2156,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:03.465373 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): free 112239259 bytes of WAL
I20260812 06:18:03.465591 17043 log_reader.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c: removed 11 log segments from log reader
I20260812 06:18:03.465653 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000003 (ops 12-16)
I20260812 06:18:03.465709 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000004 (ops 17-21)
I20260812 06:18:03.465766 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000005 (ops 22-26)
I20260812 06:18:03.465809 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000006 (ops 27-31)
I20260812 06:18:03.465868 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000007 (ops 32-36)
I20260812 06:18:03.465905 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000008 (ops 37-40)
I20260812 06:18:03.465934 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000009 (ops 41-45)
I20260812 06:18:03.465965 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000010 (ops 46-50)
I20260812 06:18:03.465993 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000011 (ops 51-55)
I20260812 06:18:03.466037 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000012 (ops 56-60)
I20260812 06:18:03.466078 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000013 (ops 61-65)
I20260812 06:18:03.490999 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:03.491569 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): 462 bytes on disk
I20260812 06:18:03.492143 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:03.492671 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:03.510145 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":5175,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:03.510646 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): free 12017983 bytes of WAL
I20260812 06:18:03.510869 17043 log_reader.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c: removed 1 log segments from log reader
I20260812 06:18:03.510915 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000014 (ops 66-70)
I20260812 06:18:03.513649 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:03.513983 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:03.526997 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":4722,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:03.527519 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:03.797211 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.270s	user 0.176s	sys 0.092s 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":719,"lbm_read_time_us":17189,"lbm_reads_lt_1ms":766,"lbm_write_time_us":45762,"lbm_writes_lt_1ms":743,"mutex_wait_us":341,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":86784,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:18:03.798125 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=18.063937
I20260812 06:18:03.864820 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.066s	user 0.045s	sys 0.015s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28265,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:03.865346 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:03.879774 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.880206 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:04.097218 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.217s	user 0.141s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":15283,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35395,"lbm_writes_lt_1ms":643,"mutex_wait_us":248,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":3000}
I20260812 06:18:04.097997 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:04.165961 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.068s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21726,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.166543 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:04.177505 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.178076 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:04.353785 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.175s	user 0.100s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1234,"lbm_read_time_us":12420,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28272,"lbm_writes_lt_1ms":543,"mutex_wait_us":422,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":2500}
I20260812 06:18:04.354343 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:04.414930 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.060s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.415778 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:04.426846 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.427325 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:04.610700 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.183s	user 0.114s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":11947,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31646,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:04.611268 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=11.118625
I20260812 06:18:04.652650 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.041s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16871,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:04.653391 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:04.682520 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.029s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6782,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:04.683082 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:04.698693 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.699347 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:04.889662 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.190s	user 0.143s	sys 0.040s 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":622,"lbm_read_time_us":12164,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30546,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30080,"update_count":2500}
I20260812 06:18:04.890260 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:04.956136 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.066s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21253,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.956841 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:04.967867 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.968367 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:05.016189 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.048s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1819,"drs_written":1,"lbm_read_time_us":122,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2087,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:05.016903 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): free 108988509 bytes of WAL
I20260812 06:18:05.017138 17043 log_reader.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c: removed 11 log segments from log reader
I20260812 06:18:05.017180 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000015 (ops 71-75)
I20260812 06:18:05.017212 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000016 (ops 76-80)
I20260812 06:18:05.017277 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000017 (ops 81-85)
I20260812 06:18:05.017308 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000018 (ops 86-90)
I20260812 06:18:05.017349 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000019 (ops 91-95)
I20260812 06:18:05.017408 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000020 (ops 96-100)
I20260812 06:18:05.017450 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000021 (ops 101-104)
I20260812 06:18:05.017493 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000022 (ops 105-109)
I20260812 06:18:05.017532 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000023 (ops 110-114)
I20260812 06:18:05.017570 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000024 (ops 115-119)
I20260812 06:18:05.017609 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000025 (ops 120-124)
I20260812 06:18:05.040126 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:05.040632 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): 447 bytes on disk
I20260812 06:18:05.041083 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.041625 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.066152 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.066608 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.077615 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.078218 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:05.323050 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.245s	user 0.172s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":541,"lbm_read_time_us":15289,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37473,"lbm_writes_lt_1ms":743,"mutex_wait_us":50,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":28672,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:18:05.323803 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=18.063937
I20260812 06:18:05.395007 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.071s	user 0.038s	sys 0.014s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25608,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:05.395555 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.406450 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.407277 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:05.613269 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.206s	user 0.154s	sys 0.049s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":674,"lbm_read_time_us":12357,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32668,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":3000}
I20260812 06:18:05.613891 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=15.087375
I20260812 06:18:05.668788 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.055s	user 0.037s	sys 0.016s Metrics: {"bytes_written":17189369,"delete_count":0,"lbm_write_time_us":25176,"lbm_writes_lt_1ms":422,"reinsert_count":0,"update_count":2095}
I20260812 06:18:05.669258 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.691243 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":6094,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:18:05.691994 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.707026 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.707737 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:05.916792 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.209s	user 0.144s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1757,"lbm_read_time_us":14268,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34492,"lbm_writes_lt_1ms":643,"mutex_wait_us":448,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:05.917558 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:05.980448 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.063s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22902,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.980997 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:05.993067 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4450,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.993569 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:06.177686 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.184s	user 0.139s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":470,"lbm_read_time_us":13228,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33812,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:18:06.178375 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:06.237797 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.059s	user 0.043s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.238451 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:06.256636 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.257429 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:06.435559 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.178s	user 0.140s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":12148,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29999,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":55296,"update_count":2500}
I20260812 06:18:06.436269 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=14.095187
I20260812 06:18:06.490526 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.054s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20343,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.491209 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:06.501812 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.502254 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:06.544090 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushMRSOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.042s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":177,"dirs.run_wall_time_us":1180,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2014,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:06.544778 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): free 120553628 bytes of WAL
I20260812 06:18:06.545008 17043 log_reader.cc:385] T 9ec3b7c8874e4f8da01dc95e935faa7c: removed 12 log segments from log reader
I20260812 06:18:06.545054 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000026 (ops 125-128)
I20260812 06:18:06.545082 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000027 (ops 129-133)
I20260812 06:18:06.545149 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000028 (ops 134-138)
I20260812 06:18:06.545208 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000029 (ops 139-143)
I20260812 06:18:06.545248 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000030 (ops 144-148)
I20260812 06:18:06.545290 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000031 (ops 149-153)
I20260812 06:18:06.545331 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000032 (ops 154-158)
I20260812 06:18:06.545358 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000033 (ops 159-163)
I20260812 06:18:06.545395 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000034 (ops 164-168)
I20260812 06:18:06.545434 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000035 (ops 169-172)
I20260812 06:18:06.545473 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000036 (ops 173-177)
I20260812 06:18:06.545512 17043 log.cc:1079] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: Deleting log segment in path: /tmp/dist-test-taskHotej0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515476012130-16559-0/minicluster-data/ts-0-root/wals/9ec3b7c8874e4f8da01dc95e935faa7c/wal-000000037 (ops 178-182)
I20260812 06:18:06.570888 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: LogGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:06.571491 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c): 463 bytes on disk
I20260812 06:18:06.571988 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: UndoDeltaBlockGCOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.572636 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:06.592846 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.020s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.593271 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:06.604322 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.604809 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:06.847631 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.243s	user 0.161s	sys 0.070s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":610,"lbm_read_time_us":15908,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40154,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":148,"threads_started":1,"update_count":3500}
I20260812 06:18:06.848655 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=18.063937
I20260812 06:18:06.909555 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.061s	user 0.043s	sys 0.015s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27589,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:06.910050 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=2.188937
I20260812 06:18:06.927404 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: FlushDeltaMemStoresOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.017s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.927922 17138 maintenance_manager.cc:419] P 6916ec7d5394412bb60a330b5d5119b9: Scheduling MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c): perf score=1.000000
I20260812 06:18:06.998378 16559 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.192s	user 1.832s	sys 0.264s
I20260812 06:18:07.054209 16559 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.001s	sys 0.000s
I20260812 06:18:07.054716 16559 tablet_server.cc:179] TabletServer@127.16.43.193:0 shutting down...
I20260812 06:18:07.094067 17043 maintenance_manager.cc:643] P 6916ec7d5394412bb60a330b5d5119b9: MajorDeltaCompactionOp(9ec3b7c8874e4f8da01dc95e935faa7c) complete. Timing: real 0.166s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":368,"lbm_read_time_us":11820,"lbm_reads_lt_1ms":660,"lbm_write_time_us":31165,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":3000}
I20260812 06:18:07.094868 16559 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:07.095083 16559 tablet_replica.cc:333] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9: stopping tablet replica
I20260812 06:18:07.095252 16559 raft_consensus.cc:2243] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.095494 16559 raft_consensus.cc:2272] T 9ec3b7c8874e4f8da01dc95e935faa7c P 6916ec7d5394412bb60a330b5d5119b9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.100759 16559 tablet_server.cc:196] TabletServer@127.16.43.193:0 shutdown complete.
I20260812 06:18:07.146606 16559 master.cc:562] Master@127.16.43.254:36677 shutting down...
I20260812 06:18:07.150513 16559 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:07.150717 16559 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:07.150792 16559 tablet_replica.cc:333] T 00000000000000000000000000000000 P 65ed31cbd25f42b7bf9a971387c30fd9: stopping tablet replica
I20260812 06:18:07.163205 16559 master.cc:584] Master@127.16.43.254:36677 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5656 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11227 ms total)

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