[==========] 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:21.816011  8848 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.164.62:34875
I20260812 06:17:21.817065  8848 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:21.817698  8848 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:21.824074  8862 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:21.824239  8848 server_base.cc:1061] running on GCE node
W20260812 06:17:21.824147  8860 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:21.824389  8869 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:21.824918  8848 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:21.825011  8848 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:21.825042  8848 hybrid_clock.cc:648] HybridClock initialized: now 1786515441825040 us; error 0 us; skew 500 ppm
I20260812 06:17:21.826928  8848 webserver.cc:533] Webserver started at http://127.8.164.62:33637/ using document root <none> and password file <none>
I20260812 06:17:21.827494  8848 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:21.827555  8848 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:21.827759  8848 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:21.829558  8848 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/master-0-root/instance:
uuid: "d506c3ab091d4066ba4aa51d1e048c04"
format_stamp: "Formatted at 2026-08-12 06:17:21 on dist-test-slave-2d19"
I20260812 06:17:21.833098  8848 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:17:21.835137  8877 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:21.836184  8848 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:21.836342  8848 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/master-0-root
uuid: "d506c3ab091d4066ba4aa51d1e048c04"
format_stamp: "Formatted at 2026-08-12 06:17:21 on dist-test-slave-2d19"
I20260812 06:17:21.836457  8848 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-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:21.858435  8848 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:21.859104  8848 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:21.859294  8848 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:21.867571  8848 rpc_server.cc:307] RPC server started. Bound to: 127.8.164.62:34875
I20260812 06:17:21.867583  8968 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.164.62:34875 every 8 connection(s)
I20260812 06:17:21.870599  8971 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:21.875916  8971 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: Bootstrap starting.
I20260812 06:17:21.878261  8971 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:21.879216  8971 log.cc:826] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:21.880894  8971 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: No bootstrap required, opened a new log
I20260812 06:17:21.883530  8971 raft_consensus.cc:359] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER }
I20260812 06:17:21.883705  8971 raft_consensus.cc:385] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:21.883746  8971 raft_consensus.cc:740] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d506c3ab091d4066ba4aa51d1e048c04, State: Initialized, Role: FOLLOWER
I20260812 06:17:21.884294  8971 consensus_queue.cc:260] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [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: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER }
I20260812 06:17:21.884447  8971 raft_consensus.cc:399] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:21.884495  8971 raft_consensus.cc:493] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:21.884608  8971 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:21.885347  8971 raft_consensus.cc:515] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER }
I20260812 06:17:21.885722  8971 leader_election.cc:304] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [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: d506c3ab091d4066ba4aa51d1e048c04; no voters: 
I20260812 06:17:21.886000  8971 leader_election.cc:290] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:21.886158  8976 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:21.886404  8976 raft_consensus.cc:697] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 1 LEADER]: Becoming Leader. State: Replica: d506c3ab091d4066ba4aa51d1e048c04, State: Running, Role: LEADER
I20260812 06:17:21.886813  8976 consensus_queue.cc:237] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [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: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER }
I20260812 06:17:21.887050  8971 sys_catalog.cc:565] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:21.888785  8979 sys_catalog.cc:455] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d506c3ab091d4066ba4aa51d1e048c04. Latest consensus state: current_term: 1 leader_uuid: "d506c3ab091d4066ba4aa51d1e048c04" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER } }
I20260812 06:17:21.888792  8977 sys_catalog.cc:455] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d506c3ab091d4066ba4aa51d1e048c04" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d506c3ab091d4066ba4aa51d1e048c04" member_type: VOTER } }
I20260812 06:17:21.888931  8979 sys_catalog.cc:458] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:21.888931  8977 sys_catalog.cc:458] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:21.889343  8848 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:21.889504  9002 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:21.891538  9002 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:21.896143  9002 catalog_manager.cc:1383] Generated new cluster ID: 6cf2770dd3444b5d9e00f5f7b7393554
I20260812 06:17:21.896214  9002 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:21.910338  9002 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:21.911147  9002 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:21.926268  9002 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: Generated new TSK 0
I20260812 06:17:21.926941  9002 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:21.954087  8848 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:21.956795  9010 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:21.956864  9009 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:21.957067  9013 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:21.957193  8848 server_base.cc:1061] running on GCE node
I20260812 06:17:21.957350  8848 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:21.957381  8848 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:21.957396  8848 hybrid_clock.cc:648] HybridClock initialized: now 1786515441957395 us; error 0 us; skew 500 ppm
I20260812 06:17:21.958328  8848 webserver.cc:533] Webserver started at http://127.8.164.1:40787/ using document root <none> and password file <none>
I20260812 06:17:21.958500  8848 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:21.958580  8848 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:21.958679  8848 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:21.959085  8848 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/instance:
uuid: "6398e33d6bae4a4385b41f8f3d592957"
format_stamp: "Formatted at 2026-08-12 06:17:21 on dist-test-slave-2d19"
I20260812 06:17:21.960695  8848 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:21.961691  9025 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:21.961966  8848 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:21.962049  8848 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root
uuid: "6398e33d6bae4a4385b41f8f3d592957"
format_stamp: "Formatted at 2026-08-12 06:17:21 on dist-test-slave-2d19"
I20260812 06:17:21.962144  8848 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-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:21.976779  8848 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:21.977208  8848 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:21.977689  8848 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:21.978603  8848 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:21.978657  8848 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:21.978725  8848 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:21.978768  8848 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:21.985845  8848 rpc_server.cc:307] RPC server started. Bound to: 127.8.164.1:35115
I20260812 06:17:21.985901  9143 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.164.1:35115 every 8 connection(s)
I20260812 06:17:21.999564  9146 heartbeater.cc:344] Connected to a master server at 127.8.164.62:34875
I20260812 06:17:21.999812  9146 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:22.000298  9146 heartbeater.cc:507] Master 127.8.164.62:34875 requested a full tablet report, sending...
I20260812 06:17:22.001715  8902 ts_manager.cc:194] Registered new tserver with Master: 6398e33d6bae4a4385b41f8f3d592957 (127.8.164.1:35115)
I20260812 06:17:22.002151  8848 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0156566s
I20260812 06:17:22.003163  8902 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55122
I20260812 06:17:22.011802  8902 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55126:
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:22.025766  9077 tablet_service.cc:1511] Processing CreateTablet for tablet 45f23b5993eb4ce4b407b8bf8f013871 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5dd6edde8f4745cf9c8936720eddad86]), partition=
I20260812 06:17:22.026221  9077 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 45f23b5993eb4ce4b407b8bf8f013871. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:22.028439  9163 tablet_bootstrap.cc:492] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Bootstrap starting.
I20260812 06:17:22.029547  9163 tablet_bootstrap.cc:654] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:22.030963  9163 tablet_bootstrap.cc:492] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: No bootstrap required, opened a new log
I20260812 06:17:22.031049  9163 ts_tablet_manager.cc:1403] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:22.031522  9163 raft_consensus.cc:359] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6398e33d6bae4a4385b41f8f3d592957" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 35115 } }
I20260812 06:17:22.031625  9163 raft_consensus.cc:385] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:22.031651  9163 raft_consensus.cc:740] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6398e33d6bae4a4385b41f8f3d592957, State: Initialized, Role: FOLLOWER
I20260812 06:17:22.031796  9163 consensus_queue.cc:260] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [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: "6398e33d6bae4a4385b41f8f3d592957" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 35115 } }
I20260812 06:17:22.031868  9163 raft_consensus.cc:399] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:22.031947  9163 raft_consensus.cc:493] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:22.032008  9163 raft_consensus.cc:3060] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:22.033005  9163 raft_consensus.cc:515] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6398e33d6bae4a4385b41f8f3d592957" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 35115 } }
I20260812 06:17:22.033164  9163 leader_election.cc:304] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [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: 6398e33d6bae4a4385b41f8f3d592957; no voters: 
I20260812 06:17:22.033393  9163 leader_election.cc:290] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:22.033478  9168 raft_consensus.cc:2804] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:22.033702  9168 raft_consensus.cc:697] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 1 LEADER]: Becoming Leader. State: Replica: 6398e33d6bae4a4385b41f8f3d592957, State: Running, Role: LEADER
I20260812 06:17:22.033769  9163 ts_tablet_manager.cc:1434] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:22.033916  9168 consensus_queue.cc:237] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [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: "6398e33d6bae4a4385b41f8f3d592957" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 35115 } }
I20260812 06:17:22.034143  9146 heartbeater.cc:499] Master 127.8.164.62:34875 was elected leader, sending a full tablet report...
I20260812 06:17:22.036675  8902 catalog_manager.cc:5719] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6398e33d6bae4a4385b41f8f3d592957 (127.8.164.1). New cstate: current_term: 1 leader_uuid: "6398e33d6bae4a4385b41f8f3d592957" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6398e33d6bae4a4385b41f8f3d592957" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 35115 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:22.096930  8848 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.014s	sys 0.009s
I20260812 06:17:22.237017  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=19.054940
I20260812 06:17:22.402308  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.165s	user 0.112s	sys 0.047s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":299,"delete_count":0,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":981,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42599,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":143,"threads_started":1,"update_count":1500}
I20260812 06:17:22.403450  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling LogGCOp(45f23b5993eb4ce4b407b8bf8f013871): free 20743880 bytes of WAL
I20260812 06:17:22.403771  9033 log_reader.cc:385] T 45f23b5993eb4ce4b407b8bf8f013871: removed 2 log segments from log reader
I20260812 06:17:22.403837  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000001 (ops 1-6)
I20260812 06:17:22.403898  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000002 (ops 7-11)
I20260812 06:17:22.409217  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: LogGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:22.409508  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871): 16411394 bytes on disk
I20260812 06:17:22.410082  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.410475  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:22.427026  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6416,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.427511  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:22.575830  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.148s	user 0.092s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":7205,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25659,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"thread_start_us":283,"threads_started":5,"update_count":2000}
I20260812 06:17:22.576591  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:22.621670  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.045s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14818,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.622083  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:22.633818  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.634490  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:22.756816  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.122s	user 0.099s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":7577,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25014,"lbm_writes_lt_1ms":443,"mutex_wait_us":118,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:22.757395  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:22.795346  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.038s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15515,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.795921  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:22.806524  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.807188  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:22.929734  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.122s	user 0.099s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":855,"lbm_read_time_us":9328,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22791,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:22.930253  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:22.979161  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.049s	user 0.016s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13786,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:22.979794  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:22.991092  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.991531  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:23.131780  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.140s	user 0.110s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":326,"lbm_read_time_us":10698,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23149,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:17:23.132439  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:23.181084  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.048s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16775,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.181681  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:23.197264  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.197912  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:23.325090  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.127s	user 0.115s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":127,"lbm_read_time_us":9658,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25492,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:23.325537  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:23.374364  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.049s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.374848  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:23.390614  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.391196  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:23.510754  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.119s	user 0.103s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1008,"lbm_read_time_us":7987,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23035,"lbm_writes_lt_1ms":443,"mutex_wait_us":412,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:23.512162  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=10.126437
I20260812 06:17:23.558784  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.046s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17617,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.559312  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:23.569922  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.570338  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:23.599807  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.029s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1441,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1792}
I20260812 06:17:23.600764  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:23.754356  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.153s	user 0.108s	sys 0.045s 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":888,"lbm_read_time_us":9410,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26252,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":61568,"update_count":2000}
I20260812 06:17:23.755033  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling LogGCOp(45f23b5993eb4ce4b407b8bf8f013871): free 115943176 bytes of WAL
I20260812 06:17:23.755365  9033 log_reader.cc:385] T 45f23b5993eb4ce4b407b8bf8f013871: removed 11 log segments from log reader
I20260812 06:17:23.755432  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000003 (ops 12-16)
I20260812 06:17:23.755479  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000004 (ops 17-21)
I20260812 06:17:23.755522  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000005 (ops 22-26)
I20260812 06:17:23.755564  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000006 (ops 27-31)
I20260812 06:17:23.755604  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000007 (ops 32-36)
I20260812 06:17:23.755646  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000008 (ops 37-41)
I20260812 06:17:23.755688  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000009 (ops 42-46)
I20260812 06:17:23.755731  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000010 (ops 47-51)
I20260812 06:17:23.755774  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000011 (ops 52-56)
I20260812 06:17:23.755813  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000012 (ops 57-61)
I20260812 06:17:23.755852  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000013 (ops 62-66)
I20260812 06:17:23.789294  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: LogGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.034s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:23.789937  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871): 447 bytes on disk
I20260812 06:17:23.790572  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4}
I20260812 06:17:23.791249  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:23.834156  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.043s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19257,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.834803  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:23.850237  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.850867  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:24.027828  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.177s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":10292,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31373,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:17:24.028482  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:24.079479  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.051s	user 0.039s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.079998  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:24.092101  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.092633  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:24.254565  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.162s	user 0.130s	sys 0.021s 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":1081,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31442,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:24.255067  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:24.308485  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.053s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22287,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.309005  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:24.324522  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.325138  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:24.480152  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.155s	user 0.115s	sys 0.029s 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":927,"lbm_read_time_us":9765,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29667,"lbm_writes_lt_1ms":543,"mutex_wait_us":254,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:24.480906  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:24.533349  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.052s	user 0.024s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23508,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.533898  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:24.545643  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.546131  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:24.718809  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.173s	user 0.114s	sys 0.044s 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":998,"lbm_read_time_us":10718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34584,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:17:24.719447  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:24.771463  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.052s	user 0.041s	sys 0.000s Metrics: {"bytes_written":16409919,"delete_count":0,"lbm_write_time_us":19321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.771967  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:24.787464  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.015s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.788125  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:24.952137  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.164s	user 0.099s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774706,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":433,"lbm_read_time_us":11446,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27711,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:24.952976  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:24.998489  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.045s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19617,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.999091  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:25.032222  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.033s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1577,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1978,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:25.033609  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling LogGCOp(45f23b5993eb4ce4b407b8bf8f013871): free 121006381 bytes of WAL
I20260812 06:17:25.033891  9033 log_reader.cc:385] T 45f23b5993eb4ce4b407b8bf8f013871: removed 12 log segments from log reader
I20260812 06:17:25.033996  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000014 (ops 67-71)
I20260812 06:17:25.034061  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000015 (ops 72-76)
I20260812 06:17:25.034101  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000016 (ops 77-81)
I20260812 06:17:25.034148  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000017 (ops 82-86)
I20260812 06:17:25.034192  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000018 (ops 87-91)
I20260812 06:17:25.034229  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000019 (ops 92-96)
I20260812 06:17:25.034266  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000020 (ops 97-101)
I20260812 06:17:25.034308  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000021 (ops 102-106)
I20260812 06:17:25.034349  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000022 (ops 107-111)
I20260812 06:17:25.034373  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000023 (ops 112-116)
I20260812 06:17:25.034438  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000024 (ops 117-120)
I20260812 06:17:25.034523  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000025 (ops 121-125)
I20260812 06:17:25.062031  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: LogGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:25.062572  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871): 472 bytes on disk
I20260812 06:17:25.063294  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.063920  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=3.181125
I20260812 06:17:25.082279  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":7246,"lbm_writes_lt_1ms":131,"mutex_wait_us":104,"reinsert_count":0,"update_count":640}
I20260812 06:17:25.082690  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.196750
I20260812 06:17:25.090782  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":2995,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:25.091236  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:25.320956  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.229s	user 0.156s	sys 0.066s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":4451,"dirs.run_cpu_time_us":1151,"dirs.run_wall_time_us":9011,"lbm_read_time_us":13370,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39765,"lbm_writes_lt_1ms":643,"mutex_wait_us":3848,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23680,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:17:25.321483  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=16.079562
I20260812 06:17:25.377434  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.056s	user 0.034s	sys 0.020s Metrics: {"bytes_written":18009849,"delete_count":0,"lbm_write_time_us":24854,"lbm_writes_lt_1ms":442,"reinsert_count":0,"update_count":2195}
I20260812 06:17:25.377907  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.196750
I20260812 06:17:25.388155  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.010s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2912934,"delete_count":0,"lbm_write_time_us":2876,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:17:25.388731  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:25.402261  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5046,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.402771  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:25.602051  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.199s	user 0.130s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877188,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":794,"lbm_read_time_us":12974,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34233,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:25.602664  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:25.665876  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.063s	user 0.017s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20720,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.666322  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:25.677027  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.677770  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:25.854220  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.176s	user 0.120s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":13027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29526,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:17:25.854753  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:25.909328  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.054s	user 0.010s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19828,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.909884  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:25.925755  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.926359  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:26.118208  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.192s	user 0.128s	sys 0.050s 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":617,"lbm_read_time_us":13372,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31147,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:17:26.119132  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:26.187080  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.068s	user 0.030s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22759,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.187695  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:26.199609  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.200393  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:26.410214  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.210s	user 0.147s	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":626,"lbm_read_time_us":12783,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36447,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.410753  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:26.460457  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.050s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21500,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.460966  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:26.479681  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.019s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.480227  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:26.654856  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.174s	user 0.102s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":999,"lbm_read_time_us":11220,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29375,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:26.655627  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=14.095187
I20260812 06:17:26.706190  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.050s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.706681  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:26.718662  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.719161  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:26.749317  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushMRSOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.030s	user 0.028s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1361,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1854,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:26.750170  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871): 493 bytes on disk
I20260812 06:17:26.750661  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: UndoDeltaBlockGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.751226  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:26.762179  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.762604  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling LogGCOp(45f23b5993eb4ce4b407b8bf8f013871): free 136728568 bytes of WAL
I20260812 06:17:26.762821  9033 log_reader.cc:385] T 45f23b5993eb4ce4b407b8bf8f013871: removed 13 log segments from log reader
I20260812 06:17:26.762882  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000026 (ops 126-130)
I20260812 06:17:26.762938  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000027 (ops 131-135)
I20260812 06:17:26.763001  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000028 (ops 136-140)
I20260812 06:17:26.763041  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000029 (ops 141-145)
I20260812 06:17:26.763077  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000030 (ops 146-150)
I20260812 06:17:26.763113  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000031 (ops 151-155)
I20260812 06:17:26.763150  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000032 (ops 156-160)
I20260812 06:17:26.763187  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000033 (ops 161-165)
I20260812 06:17:26.763249  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000034 (ops 166-170)
I20260812 06:17:26.763311  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000035 (ops 171-175)
I20260812 06:17:26.763353  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000036 (ops 176-180)
I20260812 06:17:26.763396  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000037 (ops 181-185)
I20260812 06:17:26.763432  9033 log.cc:1079] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/45f23b5993eb4ce4b407b8bf8f013871/wal-000000038 (ops 186-190)
I20260812 06:17:26.792883  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: LogGCOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:26.793341  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=1.000000
I20260812 06:17:26.985877  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: MajorDeltaCompactionOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.192s	user 0.134s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877217,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1042,"lbm_read_time_us":14727,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33161,"lbm_writes_lt_1ms":643,"mutex_wait_us":324,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:17:26.986686  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=15.087375
I20260812 06:17:26.998169  8848 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.901s	user 1.837s	sys 0.166s
I20260812 06:17:27.038873  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.052s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":18033,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:27.038988  8848 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.001s	sys 0.004s
I20260812 06:17:27.039431  9147 maintenance_manager.cc:419] P 6398e33d6bae4a4385b41f8f3d592957: Scheduling FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871): perf score=2.188937
I20260812 06:17:27.039666  8848 tablet_server.cc:179] TabletServer@127.8.164.1:0 shutting down...
I20260812 06:17:27.051978  9033 maintenance_manager.cc:643] P 6398e33d6bae4a4385b41f8f3d592957: FlushDeltaMemStoresOp(45f23b5993eb4ce4b407b8bf8f013871) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.052546  8848 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:27.052881  8848 tablet_replica.cc:333] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957: stopping tablet replica
I20260812 06:17:27.053117  8848 raft_consensus.cc:2243] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.053299  8848 raft_consensus.cc:2272] T 45f23b5993eb4ce4b407b8bf8f013871 P 6398e33d6bae4a4385b41f8f3d592957 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.057420  8848 tablet_server.cc:196] TabletServer@127.8.164.1:0 shutdown complete.
I20260812 06:17:27.061547  8848 master.cc:562] Master@127.8.164.62:34875 shutting down...
I20260812 06:17:27.065233  8848 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.065399  8848 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.065483  8848 tablet_replica.cc:333] T 00000000000000000000000000000000 P d506c3ab091d4066ba4aa51d1e048c04: stopping tablet replica
I20260812 06:17:27.077597  8848 master.cc:584] Master@127.8.164.62:34875 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5349 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:27.164378  8848 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.164.62:44795
I20260812 06:17:27.164812  8848 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:27.166991  9194 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:27.167040  9195 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:27.167140  8848 server_base.cc:1061] running on GCE node
W20260812 06:17:27.167104  9198 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:27.167448  8848 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:27.167490  8848 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:27.167505  8848 hybrid_clock.cc:648] HybridClock initialized: now 1786515447167506 us; error 0 us; skew 500 ppm
I20260812 06:17:27.168390  8848 webserver.cc:533] Webserver started at http://127.8.164.62:45389/ using document root <none> and password file <none>
I20260812 06:17:27.168526  8848 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:27.168581  8848 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:27.168641  8848 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:27.168969  8848 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/master-0-root/instance:
uuid: "698cf0ae29e54fb3acc5449ce3506d8b"
format_stamp: "Formatted at 2026-08-12 06:17:27 on dist-test-slave-2d19"
I20260812 06:17:27.170333  8848 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:27.171171  9204 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:27.171406  8848 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:27.171497  8848 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/master-0-root
uuid: "698cf0ae29e54fb3acc5449ce3506d8b"
format_stamp: "Formatted at 2026-08-12 06:17:27 on dist-test-slave-2d19"
I20260812 06:17:27.171589  8848 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-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:27.187173  8848 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:27.187590  8848 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:27.192112  8848 rpc_server.cc:307] RPC server started. Bound to: 127.8.164.62:44795
I20260812 06:17:27.195813  9298 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.164.62:44795 every 8 connection(s)
I20260812 06:17:27.197404  9299 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:27.201817  9299 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b: Bootstrap starting.
I20260812 06:17:27.202615  9299 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:27.203701  9299 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b: No bootstrap required, opened a new log
I20260812 06:17:27.204100  9299 raft_consensus.cc:359] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER }
I20260812 06:17:27.204226  9299 raft_consensus.cc:385] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:27.204301  9299 raft_consensus.cc:740] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 698cf0ae29e54fb3acc5449ce3506d8b, State: Initialized, Role: FOLLOWER
I20260812 06:17:27.204463  9299 consensus_queue.cc:260] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [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: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER }
I20260812 06:17:27.204558  9299 raft_consensus.cc:399] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:27.204607  9299 raft_consensus.cc:493] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:27.204663  9299 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:27.205345  9299 raft_consensus.cc:515] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER }
I20260812 06:17:27.205498  9299 leader_election.cc:304] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [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: 698cf0ae29e54fb3acc5449ce3506d8b; no voters: 
I20260812 06:17:27.205696  9299 leader_election.cc:290] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:27.205821  9304 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:27.206080  9304 raft_consensus.cc:697] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 1 LEADER]: Becoming Leader. State: Replica: 698cf0ae29e54fb3acc5449ce3506d8b, State: Running, Role: LEADER
I20260812 06:17:27.206183  9299 sys_catalog.cc:565] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:27.206236  9304 consensus_queue.cc:237] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [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: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER }
I20260812 06:17:27.206673  9307 sys_catalog.cc:455] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER } }
I20260812 06:17:27.206780  9307 sys_catalog.cc:458] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:27.206691  9308 sys_catalog.cc:455] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 698cf0ae29e54fb3acc5449ce3506d8b. Latest consensus state: current_term: 1 leader_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "698cf0ae29e54fb3acc5449ce3506d8b" member_type: VOTER } }
I20260812 06:17:27.206881  9308 sys_catalog.cc:458] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:27.207362  9323 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:27.208029  9323 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:27.208225  8848 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:27.209828  9323 catalog_manager.cc:1383] Generated new cluster ID: 3ca5662b4bac49ebaa884d17758cc9b0
I20260812 06:17:27.209885  9323 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:27.227373  9323 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:27.227921  9323 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:27.232754  9323 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b: Generated new TSK 0
I20260812 06:17:27.232923  9323 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:27.240509  8848 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:27.242468  9343 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:27.242591  9346 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:27.242892  8848 server_base.cc:1061] running on GCE node
W20260812 06:17:27.243366  9348 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:27.243597  8848 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:27.243659  8848 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:27.243693  8848 hybrid_clock.cc:648] HybridClock initialized: now 1786515447243692 us; error 0 us; skew 500 ppm
I20260812 06:17:27.244628  8848 webserver.cc:533] Webserver started at http://127.8.164.1:37343/ using document root <none> and password file <none>
I20260812 06:17:27.244809  8848 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:27.244884  8848 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:27.245011  8848 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:27.245409  8848 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/instance:
uuid: "05d741c2f4ae4b76a9ee32652282ed62"
format_stamp: "Formatted at 2026-08-12 06:17:27 on dist-test-slave-2d19"
I20260812 06:17:27.246897  8848 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:27.247778  9357 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:27.248020  8848 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:27.248111  8848 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root
uuid: "05d741c2f4ae4b76a9ee32652282ed62"
format_stamp: "Formatted at 2026-08-12 06:17:27 on dist-test-slave-2d19"
I20260812 06:17:27.248200  8848 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-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:27.289088  8848 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:27.289513  8848 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:27.289860  8848 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:27.290400  8848 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:27.290441  8848 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:27.290652  8848 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:27.290832  8848 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:27.295639  8848 rpc_server.cc:307] RPC server started. Bound to: 127.8.164.1:33659
I20260812 06:17:27.297120  9462 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.164.1:33659 every 8 connection(s)
I20260812 06:17:27.305099  9468 heartbeater.cc:344] Connected to a master server at 127.8.164.62:44795
I20260812 06:17:27.305212  9468 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:27.305438  9468 heartbeater.cc:507] Master 127.8.164.62:44795 requested a full tablet report, sending...
I20260812 06:17:27.306097  9241 ts_manager.cc:194] Registered new tserver with Master: 05d741c2f4ae4b76a9ee32652282ed62 (127.8.164.1:33659)
I20260812 06:17:27.306625  8848 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009958401s
I20260812 06:17:27.306885  9241 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44534
I20260812 06:17:27.313433  9241 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44548:
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:27.321867  9403 tablet_service.cc:1511] Processing CreateTablet for tablet 0ffafb1cabad4bfeb7f4a5e28231f162 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f14bcde293ab468e9df7effba6f958d1]), partition=
I20260812 06:17:27.322108  9403 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0ffafb1cabad4bfeb7f4a5e28231f162. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:27.323877  9491 tablet_bootstrap.cc:492] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Bootstrap starting.
I20260812 06:17:27.324887  9491 tablet_bootstrap.cc:654] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:27.325913  9491 tablet_bootstrap.cc:492] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: No bootstrap required, opened a new log
I20260812 06:17:27.326009  9491 ts_tablet_manager.cc:1403] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:27.326421  9491 raft_consensus.cc:359] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05d741c2f4ae4b76a9ee32652282ed62" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 33659 } }
I20260812 06:17:27.326508  9491 raft_consensus.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:27.326574  9491 raft_consensus.cc:740] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 05d741c2f4ae4b76a9ee32652282ed62, State: Initialized, Role: FOLLOWER
I20260812 06:17:27.326742  9491 consensus_queue.cc:260] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [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: "05d741c2f4ae4b76a9ee32652282ed62" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 33659 } }
I20260812 06:17:27.326814  9491 raft_consensus.cc:399] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:27.326874  9491 raft_consensus.cc:493] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:27.326930  9491 raft_consensus.cc:3060] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:27.327888  9491 raft_consensus.cc:515] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05d741c2f4ae4b76a9ee32652282ed62" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 33659 } }
I20260812 06:17:27.328030  9491 leader_election.cc:304] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [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: 05d741c2f4ae4b76a9ee32652282ed62; no voters: 
I20260812 06:17:27.328281  9491 leader_election.cc:290] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:27.328423  9496 raft_consensus.cc:2804] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:27.328637  9491 ts_tablet_manager.cc:1434] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:27.328655  9468 heartbeater.cc:499] Master 127.8.164.62:44795 was elected leader, sending a full tablet report...
I20260812 06:17:27.328670  9496 raft_consensus.cc:697] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 1 LEADER]: Becoming Leader. State: Replica: 05d741c2f4ae4b76a9ee32652282ed62, State: Running, Role: LEADER
I20260812 06:17:27.328836  9496 consensus_queue.cc:237] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [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: "05d741c2f4ae4b76a9ee32652282ed62" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 33659 } }
I20260812 06:17:27.330027  9241 catalog_manager.cc:5719] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 reported cstate change: term changed from 0 to 1, leader changed from <none> to 05d741c2f4ae4b76a9ee32652282ed62 (127.8.164.1). New cstate: current_term: 1 leader_uuid: "05d741c2f4ae4b76a9ee32652282ed62" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "05d741c2f4ae4b76a9ee32652282ed62" member_type: VOTER last_known_addr { host: "127.8.164.1" port: 33659 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:27.390434  8848 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.020s	sys 0.003s
I20260812 06:17:27.547771  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=23.023690
I20260812 06:17:27.717366  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.169s	user 0.133s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1031,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45506,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:17:27.717994  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): free 20743831 bytes of WAL
I20260812 06:17:27.718223  9364 log_reader.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162: removed 2 log segments from log reader
I20260812 06:17:27.718291  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000001 (ops 1-6)
I20260812 06:17:27.718348  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000002 (ops 7-11)
I20260812 06:17:27.722569  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:27.722935  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:27.738374  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.738859  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:27.877955  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.139s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":418,"lbm_read_time_us":10382,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23994,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":325,"threads_started":5,"update_count":2000}
I20260812 06:17:27.878544  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=11.118625
I20260812 06:17:27.921978  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.043s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17139,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.922420  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): 20513813 bytes on disk
I20260812 06:17:27.922771  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.923146  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:27.948086  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5634,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.948570  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:27.961913  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5053,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.962430  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:28.147305  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.185s	user 0.107s	sys 0.073s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":418,"lbm_read_time_us":11605,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31896,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:17:28.147861  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:28.218505  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.070s	user 0.035s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":29894,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.219004  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:28.231995  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.237336  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:28.448489  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.209s	user 0.163s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":15154,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30632,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:28.449218  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:28.505990  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.057s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22603,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.506594  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:28.518695  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.520129  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:28.704303  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.184s	user 0.111s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":639,"lbm_read_time_us":11882,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29543,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:28.704902  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:28.754412  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.049s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22224,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.754997  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:28.775655  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.020s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.776382  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:28.952404  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.176s	user 0.110s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1020,"lbm_read_time_us":10989,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28793,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:17:28.952885  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:29.010053  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.057s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23960,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.010565  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:29.021322  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.021869  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:29.060644  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.039s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1632,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2541,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:29.061264  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): free 124257284 bytes of WAL
I20260812 06:17:29.061479  9364 log_reader.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162: removed 12 log segments from log reader
I20260812 06:17:29.061540  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000003 (ops 12-16)
I20260812 06:17:29.061596  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000004 (ops 17-21)
I20260812 06:17:29.061652  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000005 (ops 22-26)
I20260812 06:17:29.061693  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000006 (ops 27-31)
I20260812 06:17:29.061730  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000007 (ops 32-36)
I20260812 06:17:29.061769  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000008 (ops 37-41)
I20260812 06:17:29.061805  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000009 (ops 42-46)
I20260812 06:17:29.061841  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000010 (ops 47-51)
I20260812 06:17:29.061877  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000011 (ops 52-56)
I20260812 06:17:29.061913  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000012 (ops 57-61)
I20260812 06:17:29.061954  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000013 (ops 62-66)
I20260812 06:17:29.061990  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000014 (ops 67-70)
I20260812 06:17:29.088523  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:29.088878  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): 462 bytes on disk
I20260812 06:17:29.089262  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.089744  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=3.181125
I20260812 06:17:29.108594  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.019s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:29.109038  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:29.122049  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5002,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.122591  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:29.363039  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.240s	user 0.151s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":876,"lbm_read_time_us":14943,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41710,"lbm_writes_lt_1ms":743,"mutex_wait_us":262,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:17:29.363713  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=18.063937
I20260812 06:17:29.435575  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.072s	user 0.036s	sys 0.019s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25908,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.436115  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:29.450861  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5724,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.451526  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:29.646433  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.195s	user 0.095s	sys 0.098s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":647,"lbm_read_time_us":13356,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31047,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":3000}
I20260812 06:17:29.647184  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:29.693869  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.046s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20776,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.694443  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:29.709998  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.710482  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:29.893548  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.183s	user 0.125s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":12945,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32018,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:17:29.894312  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:29.938647  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.044s	user 0.024s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20067,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.939153  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:29.949677  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.950073  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:30.121182  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.171s	user 0.136s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12120,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28070,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:17:30.121858  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:30.171794  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.050s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18245,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.172606  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:30.184545  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.185026  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:30.356494  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.171s	user 0.117s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":12528,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28728,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:17:30.357197  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:30.416947  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.060s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22034,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.417479  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:30.428007  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.428473  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:30.459889  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.031s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1505,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1436,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:30.460579  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): 447 bytes on disk
I20260812 06:17:30.460963  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.461437  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:30.634593  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.173s	user 0.107s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":740,"lbm_read_time_us":10836,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29175,"lbm_writes_lt_1ms":543,"mutex_wait_us":235,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:17:30.635355  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): free 112692315 bytes of WAL
I20260812 06:17:30.635607  9364 log_reader.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162: removed 11 log segments from log reader
I20260812 06:17:30.635703  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000015 (ops 71-75)
I20260812 06:17:30.635767  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000016 (ops 76-80)
I20260812 06:17:30.635819  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000017 (ops 81-85)
I20260812 06:17:30.635871  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000018 (ops 86-90)
I20260812 06:17:30.635918  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000019 (ops 91-95)
I20260812 06:17:30.635954  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000020 (ops 96-100)
I20260812 06:17:30.635989  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000021 (ops 101-105)
I20260812 06:17:30.636067  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000022 (ops 106-110)
I20260812 06:17:30.636112  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000023 (ops 111-115)
I20260812 06:17:30.636148  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000024 (ops 116-120)
I20260812 06:17:30.636183  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000025 (ops 121-125)
I20260812 06:17:30.659879  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.024s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:17:30.660356  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=15.087375
I20260812 06:17:30.727424  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.067s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16820151,"delete_count":0,"lbm_write_time_us":19970,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:30.727999  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=6.157687
I20260812 06:17:30.756033  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.028s	user 0.014s	sys 0.011s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":11778,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:30.756734  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:30.966657  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.210s	user 0.144s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":12689,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38748,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:30.967370  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:31.027029  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.059s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.027796  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:31.044721  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.045238  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:31.221553  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.176s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":10912,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29999,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:31.222230  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=14.095187
I20260812 06:17:31.284495  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.062s	user 0.047s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21928,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.285185  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:31.296875  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.297344  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:31.484660  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.187s	user 0.123s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":12972,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31118,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:17:31.485256  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=11.118625
I20260812 06:17:31.520140  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.035s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14699,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.520886  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:31.538776  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.018s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5557,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.539299  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:31.675552  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.136s	user 0.101s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":9373,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26042,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:31.676453  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=11.118625
I20260812 06:17:31.712109  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.035s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15014,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.713006  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:31.726827  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4929,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.727322  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:31.851526  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.124s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":7743,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25512,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.852244  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=10.126437
I20260812 06:17:31.890120  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15420,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.890632  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:31.905234  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.905807  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:31.930320  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushMRSOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.024s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1516,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1344,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1792}
I20260812 06:17:31.931187  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): free 112239591 bytes of WAL
I20260812 06:17:31.931485  9364 log_reader.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162: removed 11 log segments from log reader
I20260812 06:17:31.931556  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000026 (ops 126-130)
I20260812 06:17:31.931612  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000027 (ops 131-135)
I20260812 06:17:31.931650  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000028 (ops 136-140)
I20260812 06:17:31.931686  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000029 (ops 141-144)
I20260812 06:17:31.931720  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000030 (ops 145-149)
I20260812 06:17:31.931757  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000031 (ops 150-154)
I20260812 06:17:31.931797  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000032 (ops 155-159)
I20260812 06:17:31.931836  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000033 (ops 160-164)
I20260812 06:17:31.931875  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000034 (ops 165-169)
I20260812 06:17:31.931929  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000035 (ops 170-174)
I20260812 06:17:31.931968  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000036 (ops 175-179)
I20260812 06:17:31.957144  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:31.957639  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=6.157687
I20260812 06:17:31.978453  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.021s	user 0.009s	sys 0.009s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":8377,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:31.979007  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): free 8767145 bytes of WAL
I20260812 06:17:31.979301  9364 log_reader.cc:385] T 0ffafb1cabad4bfeb7f4a5e28231f162: removed 1 log segments from log reader
I20260812 06:17:31.979373  9364 log.cc:1079] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: Deleting log segment in path: /tmp/dist-test-taskzibSfp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515441805169-8848-0/minicluster-data/ts-0-root/wals/0ffafb1cabad4bfeb7f4a5e28231f162/wal-000000037 (ops 180-184)
I20260812 06:17:31.981760  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: LogGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:31.982075  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:32.153008  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.171s	user 0.118s	sys 0.053s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28507976,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":159,"lbm_read_time_us":10556,"lbm_reads_lt_1ms":655,"lbm_write_time_us":35710,"lbm_writes_lt_1ms":633,"mutex_wait_us":64,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":73,"threads_started":1,"update_count":2950}
I20260812 06:17:32.153609  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=15.087375
I20260812 06:17:32.216761  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.063s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":24417,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:32.217239  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162): 463 bytes on disk
I20260812 06:17:32.217662  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: UndoDeltaBlockGCOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.218192  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=2.188937
I20260812 06:17:32.229621  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.230309  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:32.345631  8848 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.955s	user 1.806s	sys 0.234s
I20260812 06:17:32.381798  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.151s	user 0.120s	sys 0.029s Metrics: {"cfile_cache_miss":542,"cfile_cache_miss_bytes":25225928,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":10788,"lbm_reads_lt_1ms":578,"lbm_write_time_us":30868,"lbm_writes_lt_1ms":553,"peak_mem_usage":63526250,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2550}
I20260812 06:17:32.382568  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=10.126437
I20260812 06:17:32.411744  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: FlushDeltaMemStoresOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.029s	user 0.023s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13035,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:32.412485  9470 maintenance_manager.cc:419] P 05d741c2f4ae4b76a9ee32652282ed62: Scheduling MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162): perf score=1.000000
I20260812 06:17:32.418831  8848 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:17:32.419358  8848 tablet_server.cc:179] TabletServer@127.8.164.1:0 shutting down...
I20260812 06:17:32.516402  9364 maintenance_manager.cc:643] P 05d741c2f4ae4b76a9ee32652282ed62: MajorDeltaCompactionOp(0ffafb1cabad4bfeb7f4a5e28231f162) complete. Timing: real 0.104s	user 0.082s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":878,"lbm_read_time_us":8741,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19907,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":47,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":1500}
I20260812 06:17:32.517087  8848 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:32.517342  8848 tablet_replica.cc:333] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62: stopping tablet replica
I20260812 06:17:32.517475  8848 raft_consensus.cc:2243] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:32.517663  8848 raft_consensus.cc:2272] T 0ffafb1cabad4bfeb7f4a5e28231f162 P 05d741c2f4ae4b76a9ee32652282ed62 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:32.532904  8848 tablet_server.cc:196] TabletServer@127.8.164.1:0 shutdown complete.
I20260812 06:17:32.549353  8848 master.cc:562] Master@127.8.164.62:44795 shutting down...
I20260812 06:17:32.552928  8848 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:32.553145  8848 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:32.553236  8848 tablet_replica.cc:333] T 00000000000000000000000000000000 P 698cf0ae29e54fb3acc5449ce3506d8b: stopping tablet replica
I20260812 06:17:32.565416  8848 master.cc:584] Master@127.8.164.62:44795 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5489 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10839 ms total)

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