[==========] 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:20.148799  8592 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.100.62:34433
I20260812 06:17:20.149842  8592 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:20.150411  8592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:20.156705  8610 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:20.156762  8592 server_base.cc:1061] running on GCE node
W20260812 06:17:20.156912  8605 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:20.157096  8606 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:20.157605  8592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:20.157694  8592 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:20.157730  8592 hybrid_clock.cc:648] HybridClock initialized: now 1786515440157728 us; error 0 us; skew 500 ppm
I20260812 06:17:20.159438  8592 webserver.cc:533] Webserver started at http://127.8.100.62:44389/ using document root <none> and password file <none>
I20260812 06:17:20.159937  8592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:20.159996  8592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:20.160198  8592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:20.161880  8592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/master-0-root/instance:
uuid: "ce7d8e5bf0984997b396ec37dc9ba6de"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-7lbf"
I20260812 06:17:20.165268  8592 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:20.167274  8619 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:20.168238  8592 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:20.168332  8592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/master-0-root
uuid: "ce7d8e5bf0984997b396ec37dc9ba6de"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-7lbf"
I20260812 06:17:20.168412  8592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-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:20.182135  8592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:20.182696  8592 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:20.182824  8592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:20.189947  8592 rpc_server.cc:307] RPC server started. Bound to: 127.8.100.62:34433
I20260812 06:17:20.189981  8699 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.100.62:34433 every 8 connection(s)
I20260812 06:17:20.192204  8700 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:20.197674  8700 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: Bootstrap starting.
I20260812 06:17:20.200058  8700 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:20.201020  8700 log.cc:826] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:20.202957  8700 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: No bootstrap required, opened a new log
I20260812 06:17:20.205932  8700 raft_consensus.cc:359] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER }
I20260812 06:17:20.206117  8700 raft_consensus.cc:385] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:20.206189  8700 raft_consensus.cc:740] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ce7d8e5bf0984997b396ec37dc9ba6de, State: Initialized, Role: FOLLOWER
I20260812 06:17:20.206797  8700 consensus_queue.cc:260] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [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: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER }
I20260812 06:17:20.206969  8700 raft_consensus.cc:399] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:20.207033  8700 raft_consensus.cc:493] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:20.207163  8700 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:20.207983  8700 raft_consensus.cc:515] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER }
I20260812 06:17:20.208423  8700 leader_election.cc:304] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [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: ce7d8e5bf0984997b396ec37dc9ba6de; no voters: 
I20260812 06:17:20.208737  8700 leader_election.cc:290] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:20.208850  8705 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:20.209082  8705 raft_consensus.cc:697] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 1 LEADER]: Becoming Leader. State: Replica: ce7d8e5bf0984997b396ec37dc9ba6de, State: Running, Role: LEADER
I20260812 06:17:20.209568  8705 consensus_queue.cc:237] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [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: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER }
I20260812 06:17:20.209789  8700 sys_catalog.cc:565] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:20.211424  8713 sys_catalog.cc:455] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER } }
I20260812 06:17:20.211408  8714 sys_catalog.cc:455] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [sys.catalog]: SysCatalogTable state changed. Reason: New leader ce7d8e5bf0984997b396ec37dc9ba6de. Latest consensus state: current_term: 1 leader_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ce7d8e5bf0984997b396ec37dc9ba6de" member_type: VOTER } }
I20260812 06:17:20.211553  8714 sys_catalog.cc:458] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:20.211553  8713 sys_catalog.cc:458] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:20.211964  8733 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:20.212034  8592 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:20.214174  8733 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:20.219051  8733 catalog_manager.cc:1383] Generated new cluster ID: 531062a959db4f54b2c348791a1f5e32
I20260812 06:17:20.219110  8733 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:20.246500  8733 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:20.247361  8733 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:20.254381  8733 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: Generated new TSK 0
I20260812 06:17:20.254958  8733 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:20.276721  8592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:20.279316  8751 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:20.279513  8592 server_base.cc:1061] running on GCE node
W20260812 06:17:20.279649  8747 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:20.279770  8755 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:20.279939  8592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:20.279989  8592 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:20.280010  8592 hybrid_clock.cc:648] HybridClock initialized: now 1786515440280010 us; error 0 us; skew 500 ppm
I20260812 06:17:20.280829  8592 webserver.cc:533] Webserver started at http://127.8.100.1:36759/ using document root <none> and password file <none>
I20260812 06:17:20.280987  8592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:20.281037  8592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:20.281109  8592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:20.281451  8592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/instance:
uuid: "cab31887228e45f4973ac5b966156f23"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-7lbf"
I20260812 06:17:20.282873  8592 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:20.283749  8764 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:20.283963  8592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:20.284039  8592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root
uuid: "cab31887228e45f4973ac5b966156f23"
format_stamp: "Formatted at 2026-08-12 06:17:20 on dist-test-slave-7lbf"
I20260812 06:17:20.284133  8592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-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:20.289682  8592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:20.290014  8592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:20.290448  8592 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:20.291237  8592 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:20.291286  8592 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:20.291330  8592 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:20.291359  8592 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:20.297286  8592 rpc_server.cc:307] RPC server started. Bound to: 127.8.100.1:39499
I20260812 06:17:20.297341  8895 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.100.1:39499 every 8 connection(s)
I20260812 06:17:20.310065  8896 heartbeater.cc:344] Connected to a master server at 127.8.100.62:34433
I20260812 06:17:20.310305  8896 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:20.310755  8896 heartbeater.cc:507] Master 127.8.100.62:34433 requested a full tablet report, sending...
I20260812 06:17:20.312162  8650 ts_manager.cc:194] Registered new tserver with Master: cab31887228e45f4973ac5b966156f23 (127.8.100.1:39499)
I20260812 06:17:20.312268  8592 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014366841s
I20260812 06:17:20.313598  8650 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41220
I20260812 06:17:20.321086  8650 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41228:
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:20.334064  8826 tablet_service.cc:1511] Processing CreateTablet for tablet 884ff05d28dd456991a015f87a6af3f3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1bea51ed23d84c42b38a4d96860568fd]), partition=
I20260812 06:17:20.334486  8826 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 884ff05d28dd456991a015f87a6af3f3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:20.336618  8914 tablet_bootstrap.cc:492] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Bootstrap starting.
I20260812 06:17:20.337680  8914 tablet_bootstrap.cc:654] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:20.338982  8914 tablet_bootstrap.cc:492] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: No bootstrap required, opened a new log
I20260812 06:17:20.339064  8914 ts_tablet_manager.cc:1403] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:20.339502  8914 raft_consensus.cc:359] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab31887228e45f4973ac5b966156f23" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 39499 } }
I20260812 06:17:20.339599  8914 raft_consensus.cc:385] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:20.339622  8914 raft_consensus.cc:740] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cab31887228e45f4973ac5b966156f23, State: Initialized, Role: FOLLOWER
I20260812 06:17:20.339758  8914 consensus_queue.cc:260] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [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: "cab31887228e45f4973ac5b966156f23" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 39499 } }
I20260812 06:17:20.339846  8914 raft_consensus.cc:399] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:20.339919  8914 raft_consensus.cc:493] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:20.340001  8914 raft_consensus.cc:3060] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:20.340864  8914 raft_consensus.cc:515] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab31887228e45f4973ac5b966156f23" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 39499 } }
I20260812 06:17:20.340996  8914 leader_election.cc:304] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [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: cab31887228e45f4973ac5b966156f23; no voters: 
I20260812 06:17:20.341183  8914 leader_election.cc:290] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:20.341339  8916 raft_consensus.cc:2804] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:20.341629  8914 ts_tablet_manager.cc:1434] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:20.341624  8916 raft_consensus.cc:697] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 1 LEADER]: Becoming Leader. State: Replica: cab31887228e45f4973ac5b966156f23, State: Running, Role: LEADER
I20260812 06:17:20.341879  8896 heartbeater.cc:499] Master 127.8.100.62:34433 was elected leader, sending a full tablet report...
I20260812 06:17:20.341924  8916 consensus_queue.cc:237] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [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: "cab31887228e45f4973ac5b966156f23" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 39499 } }
I20260812 06:17:20.344754  8650 catalog_manager.cc:5719] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 reported cstate change: term changed from 0 to 1, leader changed from <none> to cab31887228e45f4973ac5b966156f23 (127.8.100.1). New cstate: current_term: 1 leader_uuid: "cab31887228e45f4973ac5b966156f23" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cab31887228e45f4973ac5b966156f23" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 39499 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:20.406399  8592 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.016s	sys 0.012s
I20260812 06:17:20.548525  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushMRSOp(884ff05d28dd456991a015f87a6af3f3): perf score=19.054940
I20260812 06:17:20.741899  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushMRSOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.193s	user 0.153s	sys 0.036s Metrics: {"bytes_written":15999661,"cfile_init":1,"compiler_manager_pool.queue_time_us":235,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":750,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":48524,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":135,"threads_started":1,"update_count":1950}
I20260812 06:17:20.743362  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling LogGCOp(884ff05d28dd456991a015f87a6af3f3): free 20743880 bytes of WAL
I20260812 06:17:20.743742  8777 log_reader.cc:385] T 884ff05d28dd456991a015f87a6af3f3: removed 2 log segments from log reader
I20260812 06:17:20.743867  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000001 (ops 1-6)
I20260812 06:17:20.743991  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000002 (ops 7-11)
I20260812 06:17:20.749315  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: LogGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:20.749691  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3): 16821647 bytes on disk
I20260812 06:17:20.750306  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.750774  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=3.181125
I20260812 06:17:20.769411  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.769877  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:20.779198  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3405,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.779562  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:20.977695  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.198s	user 0.133s	sys 0.056s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28507964,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":546,"lbm_read_time_us":13155,"lbm_reads_lt_1ms":659,"lbm_write_time_us":34433,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":325,"threads_started":5,"update_count":2950}
I20260812 06:17:20.978159  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=14.095187
I20260812 06:17:21.025916  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.048s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.026456  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:21.174181  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.148s	user 0.100s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":171,"lbm_read_time_us":9234,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23839,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39936,"update_count":2000}
I20260812 06:17:21.174650  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=14.095187
I20260812 06:17:21.220149  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17088,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.220734  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:21.232564  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.233143  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:21.390901  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.158s	user 0.102s	sys 0.052s 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":1049,"lbm_read_time_us":9484,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28378,"lbm_writes_lt_1ms":543,"mutex_wait_us":318,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:17:21.391495  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:21.420759  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.029s	user 0.015s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12436,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:21.421283  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:21.436699  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:21.437166  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:21.557886  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.121s	user 0.097s	sys 0.023s 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":118,"lbm_read_time_us":6841,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23640,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:21.558395  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:21.602600  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.044s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16309,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.603132  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:21.612986  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.613376  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:21.733670  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.120s	user 0.083s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":8884,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22731,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":2000}
I20260812 06:17:21.734259  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:21.786334  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.052s	user 0.013s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.786863  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:21.797844  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.798306  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:21.939750  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.141s	user 0.119s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":10531,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22821,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":130176,"update_count":2000}
I20260812 06:17:21.940412  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:21.980252  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.040s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17119,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.980744  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:21.991053  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.991631  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushMRSOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:22.020251  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushMRSOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1248,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1363,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:22.021061  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling LogGCOp(884ff05d28dd456991a015f87a6af3f3): free 121006429 bytes of WAL
I20260812 06:17:22.021283  8777 log_reader.cc:385] T 884ff05d28dd456991a015f87a6af3f3: removed 12 log segments from log reader
I20260812 06:17:22.021330  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000003 (ops 12-16)
I20260812 06:17:22.021359  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000004 (ops 17-21)
I20260812 06:17:22.021391  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000005 (ops 22-26)
I20260812 06:17:22.021422  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000006 (ops 27-31)
I20260812 06:17:22.021454  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000007 (ops 32-36)
I20260812 06:17:22.021485  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000008 (ops 37-41)
I20260812 06:17:22.021536  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000009 (ops 42-46)
I20260812 06:17:22.021570  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000010 (ops 47-50)
I20260812 06:17:22.021595  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000011 (ops 51-55)
I20260812 06:17:22.021625  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000012 (ops 56-60)
I20260812 06:17:22.021656  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000013 (ops 61-65)
I20260812 06:17:22.021687  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000014 (ops 66-70)
I20260812 06:17:22.045221  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: LogGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.024s	user 0.006s	sys 0.015s Metrics: {}
I20260812 06:17:22.045678  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3): 472 bytes on disk
I20260812 06:17:22.046167  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.046644  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=3.181125
I20260812 06:17:22.059355  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4784,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:22.059775  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling LogGCOp(884ff05d28dd456991a015f87a6af3f3): free 11564875 bytes of WAL
I20260812 06:17:22.059998  8777 log_reader.cc:385] T 884ff05d28dd456991a015f87a6af3f3: removed 1 log segments from log reader
I20260812 06:17:22.060055  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000015 (ops 71-74)
I20260812 06:17:22.062594  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: LogGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:22.062915  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.079897  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3387,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.080469  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:22.262964  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.182s	user 0.118s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":152,"lbm_read_time_us":11648,"lbm_reads_lt_1ms":670,"lbm_write_time_us":31879,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:17:22.263530  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=14.095187
I20260812 06:17:22.322145  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.058s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21558,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.322650  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.332531  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.332942  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:22.495275  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.162s	user 0.102s	sys 0.059s 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":1826,"lbm_read_time_us":12306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25227,"lbm_writes_lt_1ms":543,"mutex_wait_us":690,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:22.495775  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:22.535068  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16845,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.535643  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.551963  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4824,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.552656  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:22.697342  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.145s	user 0.110s	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":138,"lbm_read_time_us":8184,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28525,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:22.697912  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:22.733983  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.036s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14955,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.734547  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.754897  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:22.755385  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.765054  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3486,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:22.765487  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:22.909435  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.144s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":638,"lbm_read_time_us":11261,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28936,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:17:22.910175  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:22.946101  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.036s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12430563,"delete_count":0,"lbm_write_time_us":13908,"lbm_writes_lt_1ms":306,"mutex_wait_us":72,"reinsert_count":0,"update_count":1515}
I20260812 06:17:22.946666  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:22.962944  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5025,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:22.963418  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:23.075605  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.112s	user 0.096s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":843,"lbm_read_time_us":7061,"lbm_reads_lt_1ms":468,"lbm_write_time_us":20160,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:23.076925  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:23.116495  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.039s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12350,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.116981  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:23.127041  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.127502  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:23.266438  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.139s	user 0.082s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":528,"lbm_read_time_us":10272,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22534,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":708224,"update_count":2000}
I20260812 06:17:23.266999  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:23.306795  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.040s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14941,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.307300  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:23.317720  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3790,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.318318  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushMRSOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:23.344022  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushMRSOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.026s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1324,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1413,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:23.344763  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling LogGCOp(884ff05d28dd456991a015f87a6af3f3): free 112239331 bytes of WAL
I20260812 06:17:23.345000  8777 log_reader.cc:385] T 884ff05d28dd456991a015f87a6af3f3: removed 11 log segments from log reader
I20260812 06:17:23.345060  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000016 (ops 75-79)
I20260812 06:17:23.345098  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000017 (ops 80-84)
I20260812 06:17:23.345129  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000018 (ops 85-89)
I20260812 06:17:23.345161  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000019 (ops 90-94)
I20260812 06:17:23.345191  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000020 (ops 95-99)
I20260812 06:17:23.345218  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000021 (ops 100-104)
I20260812 06:17:23.345245  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000022 (ops 105-109)
I20260812 06:17:23.345276  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000023 (ops 110-114)
I20260812 06:17:23.345309  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000024 (ops 115-119)
I20260812 06:17:23.345337  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000025 (ops 120-124)
I20260812 06:17:23.345367  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000026 (ops 125-128)
I20260812 06:17:23.369879  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: LogGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:23.370245  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3): 448 bytes on disk
I20260812 06:17:23.370687  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3) 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:23.371174  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=3.181125
I20260812 06:17:23.399204  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.028s	user 0.009s	sys 0.013s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6152,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:23.399691  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:23.413967  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.414507  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:23.618022  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.203s	user 0.138s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1137,"lbm_read_time_us":14008,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34541,"lbm_writes_lt_1ms":643,"mutex_wait_us":237,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:23.619910  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=14.095187
I20260812 06:17:23.673442  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.053s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17441,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:23.674019  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:23.684226  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.684760  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:23.850550  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.166s	user 0.124s	sys 0.039s 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":617,"lbm_read_time_us":12264,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27166,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:23.851044  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:23.885437  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.034s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14842,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:23.886036  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:23.902029  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5535,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:23.902482  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:24.059949  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.157s	user 0.102s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":9595,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24306,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.060544  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:24.098855  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15535,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:24.099490  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.119330  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.020s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.119781  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.129616  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.130059  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:24.279767  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.150s	user 0.112s	sys 0.036s 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":683,"lbm_read_time_us":11623,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26141,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:17:24.280323  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=11.118625
I20260812 06:17:24.316987  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.036s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15837,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:24.317477  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.331360  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.331925  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:24.454084  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.122s	user 0.102s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":738,"lbm_read_time_us":8704,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23162,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.454584  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:24.504321  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.049s	user 0.016s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18371,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.504891  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.515208  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.515686  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:24.664876  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.149s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":10701,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24954,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:17:24.665416  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=10.126437
I20260812 06:17:24.706753  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.041s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14338,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.707288  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.717672  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.718401  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushMRSOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:24.749136  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushMRSOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1348,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1667,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:24.749994  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling LogGCOp(884ff05d28dd456991a015f87a6af3f3): free 112239552 bytes of WAL
I20260812 06:17:24.750236  8777 log_reader.cc:385] T 884ff05d28dd456991a015f87a6af3f3: removed 11 log segments from log reader
I20260812 06:17:24.750285  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000027 (ops 129-133)
I20260812 06:17:24.750320  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000028 (ops 134-138)
I20260812 06:17:24.750345  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000029 (ops 139-142)
I20260812 06:17:24.750377  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000030 (ops 143-147)
I20260812 06:17:24.750402  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000031 (ops 148-152)
I20260812 06:17:24.750432  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000032 (ops 153-157)
I20260812 06:17:24.750461  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000033 (ops 158-162)
I20260812 06:17:24.750489  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000034 (ops 163-167)
I20260812 06:17:24.750532  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000035 (ops 168-172)
I20260812 06:17:24.750566  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000036 (ops 173-177)
I20260812 06:17:24.750594  8777 log.cc:1079] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/884ff05d28dd456991a015f87a6af3f3/wal-000000037 (ops 178-182)
I20260812 06:17:24.771142  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: LogGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:24.771713  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3): 447 bytes on disk
I20260812 06:17:24.772234  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: UndoDeltaBlockGCOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.772971  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=3.181125
I20260812 06:17:24.803728  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.031s	user 0.016s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7996,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:24.804236  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:24.814884  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3902,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.815363  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:25.014971  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.199s	user 0.134s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":341,"lbm_read_time_us":15906,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32878,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:17:25.015641  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=14.095187
I20260812 06:17:25.076794  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.059s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22888,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.077320  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:25.107081  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.030s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6812,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.107612  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3): perf score=2.188937
I20260812 06:17:25.118379  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: FlushDeltaMemStoresOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.118856  8898 maintenance_manager.cc:419] P cab31887228e45f4973ac5b966156f23: Scheduling MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3): perf score=1.000000
I20260812 06:17:25.155578  8592 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.749s	user 1.662s	sys 0.190s
I20260812 06:17:25.236208  8592 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.001s	sys 0.000s
I20260812 06:17:25.236881  8592 tablet_server.cc:179] TabletServer@127.8.100.1:0 shutting down...
I20260812 06:17:25.287967  8777 maintenance_manager.cc:643] P cab31887228e45f4973ac5b966156f23: MajorDeltaCompactionOp(884ff05d28dd456991a015f87a6af3f3) complete. Timing: real 0.169s	user 0.128s	sys 0.041s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":322,"lbm_read_time_us":11507,"lbm_reads_lt_1ms":669,"lbm_write_time_us":28805,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:17:25.288727  8592 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:25.289117  8592 tablet_replica.cc:333] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23: stopping tablet replica
I20260812 06:17:25.289361  8592 raft_consensus.cc:2243] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.289619  8592 raft_consensus.cc:2272] T 884ff05d28dd456991a015f87a6af3f3 P cab31887228e45f4973ac5b966156f23 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.295109  8592 tablet_server.cc:196] TabletServer@127.8.100.1:0 shutdown complete.
I20260812 06:17:25.340214  8592 master.cc:562] Master@127.8.100.62:34433 shutting down...
I20260812 06:17:25.343474  8592 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:25.343652  8592 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:25.343734  8592 tablet_replica.cc:333] T 00000000000000000000000000000000 P ce7d8e5bf0984997b396ec37dc9ba6de: stopping tablet replica
I20260812 06:17:25.355929  8592 master.cc:584] Master@127.8.100.62:34433 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5284 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:25.443517  8592 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.100.62:34281
I20260812 06:17:25.443933  8592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:25.445972  8952 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:25.445982  8951 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:25.446103  8955 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:25.446130  8592 server_base.cc:1061] running on GCE node
I20260812 06:17:25.446389  8592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:25.446431  8592 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:25.446445  8592 hybrid_clock.cc:648] HybridClock initialized: now 1786515445446446 us; error 0 us; skew 500 ppm
I20260812 06:17:25.447173  8592 webserver.cc:533] Webserver started at http://127.8.100.62:41777/ using document root <none> and password file <none>
I20260812 06:17:25.447306  8592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:25.447347  8592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:25.447402  8592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:25.447736  8592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/master-0-root/instance:
uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-7lbf"
I20260812 06:17:25.449116  8592 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:25.450006  8967 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:25.450222  8592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:25.450291  8592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/master-0-root
uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-7lbf"
I20260812 06:17:25.450362  8592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-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:25.455469  8592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:25.455775  8592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:25.459679  8592 rpc_server.cc:307] RPC server started. Bound to: 127.8.100.62:34281
I20260812 06:17:25.463428  9061 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.100.62:34281 every 8 connection(s)
I20260812 06:17:25.463924  9062 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:25.465710  9062 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4: Bootstrap starting.
I20260812 06:17:25.466444  9062 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:25.467377  9062 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4: No bootstrap required, opened a new log
I20260812 06:17:25.467744  9062 raft_consensus.cc:359] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER }
I20260812 06:17:25.467882  9062 raft_consensus.cc:385] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:25.467922  9062 raft_consensus.cc:740] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 72ab08a773e24ff6a9de6c9c3d5eb0d4, State: Initialized, Role: FOLLOWER
I20260812 06:17:25.468061  9062 consensus_queue.cc:260] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [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: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER }
I20260812 06:17:25.468127  9062 raft_consensus.cc:399] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:25.468165  9062 raft_consensus.cc:493] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:25.468212  9062 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:25.468858  9062 raft_consensus.cc:515] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER }
I20260812 06:17:25.468973  9062 leader_election.cc:304] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [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: 72ab08a773e24ff6a9de6c9c3d5eb0d4; no voters: 
I20260812 06:17:25.469151  9062 leader_election.cc:290] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:25.469247  9069 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:25.469426  9069 raft_consensus.cc:697] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 1 LEADER]: Becoming Leader. State: Replica: 72ab08a773e24ff6a9de6c9c3d5eb0d4, State: Running, Role: LEADER
I20260812 06:17:25.469578  9062 sys_catalog.cc:565] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:25.469580  9069 consensus_queue.cc:237] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [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: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER }
I20260812 06:17:25.470005  9070 sys_catalog.cc:455] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER } }
I20260812 06:17:25.470036  9071 sys_catalog.cc:455] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 72ab08a773e24ff6a9de6c9c3d5eb0d4. Latest consensus state: current_term: 1 leader_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ab08a773e24ff6a9de6c9c3d5eb0d4" member_type: VOTER } }
I20260812 06:17:25.470167  9070 sys_catalog.cc:458] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:25.470199  9071 sys_catalog.cc:458] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:25.470840  9079 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:25.471725  9079 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:25.471951  8592 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:25.473711  9079 catalog_manager.cc:1383] Generated new cluster ID: 24b73d069ef4455cb6ae0c48e9f672a1
I20260812 06:17:25.473768  9079 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:25.477607  9079 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:25.478139  9079 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:25.486631  9079 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4: Generated new TSK 0
I20260812 06:17:25.486793  9079 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:25.487949  8592 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:25.489733  9098 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:25.489745  9095 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:25.489837  8592 server_base.cc:1061] running on GCE node
W20260812 06:17:25.489928  9102 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:25.490125  8592 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:25.490168  8592 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:25.490182  8592 hybrid_clock.cc:648] HybridClock initialized: now 1786515445490183 us; error 0 us; skew 500 ppm
I20260812 06:17:25.490952  8592 webserver.cc:533] Webserver started at http://127.8.100.1:46615/ using document root <none> and password file <none>
I20260812 06:17:25.491080  8592 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:25.491122  8592 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:25.491168  8592 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:25.491499  8592 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/instance:
uuid: "14d44795d61a4cc391b662407e1ee3f7"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-7lbf"
I20260812 06:17:25.492791  8592 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:25.493623  9109 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:25.493825  8592 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:25.493887  8592 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root
uuid: "14d44795d61a4cc391b662407e1ee3f7"
format_stamp: "Formatted at 2026-08-12 06:17:25 on dist-test-slave-7lbf"
I20260812 06:17:25.493939  8592 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-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:25.506242  8592 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:25.506554  8592 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:25.506807  8592 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:25.507262  8592 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:25.507298  8592 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.507333  8592 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:25.507362  8592 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:25.511451  8592 rpc_server.cc:307] RPC server started. Bound to: 127.8.100.1:32959
I20260812 06:17:25.512524  9218 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.100.1:32959 every 8 connection(s)
I20260812 06:17:25.520339  9224 heartbeater.cc:344] Connected to a master server at 127.8.100.62:34281
I20260812 06:17:25.520443  9224 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:25.520668  9224 heartbeater.cc:507] Master 127.8.100.62:34281 requested a full tablet report, sending...
I20260812 06:17:25.521344  8996 ts_manager.cc:194] Registered new tserver with Master: 14d44795d61a4cc391b662407e1ee3f7 (127.8.100.1:32959)
I20260812 06:17:25.522008  8592 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009915282s
I20260812 06:17:25.522159  8996 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54424
I20260812 06:17:25.528457  8996 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54436:
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:25.536389  9161 tablet_service.cc:1511] Processing CreateTablet for tablet 76d3cd9fa1d6409ab814468522197b46 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7df4ceca7b864e60b18a4c52b2a253f3]), partition=
I20260812 06:17:25.536646  9161 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 76d3cd9fa1d6409ab814468522197b46. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:25.538601  9247 tablet_bootstrap.cc:492] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Bootstrap starting.
I20260812 06:17:25.539463  9247 tablet_bootstrap.cc:654] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:25.540453  9247 tablet_bootstrap.cc:492] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: No bootstrap required, opened a new log
I20260812 06:17:25.540534  9247 ts_tablet_manager.cc:1403] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:25.540908  9247 raft_consensus.cc:359] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d44795d61a4cc391b662407e1ee3f7" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 32959 } }
I20260812 06:17:25.540994  9247 raft_consensus.cc:385] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:25.541025  9247 raft_consensus.cc:740] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 14d44795d61a4cc391b662407e1ee3f7, State: Initialized, Role: FOLLOWER
I20260812 06:17:25.541148  9247 consensus_queue.cc:260] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [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: "14d44795d61a4cc391b662407e1ee3f7" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 32959 } }
I20260812 06:17:25.541218  9247 raft_consensus.cc:399] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:25.541257  9247 raft_consensus.cc:493] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:25.541304  9247 raft_consensus.cc:3060] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:25.542119  9247 raft_consensus.cc:515] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d44795d61a4cc391b662407e1ee3f7" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 32959 } }
I20260812 06:17:25.542258  9247 leader_election.cc:304] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [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: 14d44795d61a4cc391b662407e1ee3f7; no voters: 
I20260812 06:17:25.542415  9247 leader_election.cc:290] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:25.542550  9250 raft_consensus.cc:2804] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:25.542747  9224 heartbeater.cc:499] Master 127.8.100.62:34281 was elected leader, sending a full tablet report...
I20260812 06:17:25.542732  9250 raft_consensus.cc:697] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 1 LEADER]: Becoming Leader. State: Replica: 14d44795d61a4cc391b662407e1ee3f7, State: Running, Role: LEADER
I20260812 06:17:25.542730  9247 ts_tablet_manager.cc:1434] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:25.542903  9250 consensus_queue.cc:237] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [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: "14d44795d61a4cc391b662407e1ee3f7" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 32959 } }
I20260812 06:17:25.544178  8996 catalog_manager.cc:5719] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 14d44795d61a4cc391b662407e1ee3f7 (127.8.100.1). New cstate: current_term: 1 leader_uuid: "14d44795d61a4cc391b662407e1ee3f7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d44795d61a4cc391b662407e1ee3f7" member_type: VOTER last_known_addr { host: "127.8.100.1" port: 32959 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:25.598158  8592 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.013s	sys 0.008s
I20260812 06:17:25.763072  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushMRSOp(76d3cd9fa1d6409ab814468522197b46): perf score=23.023690
I20260812 06:17:25.913391  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushMRSOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.150s	user 0.110s	sys 0.036s Metrics: {"bytes_written":12676712,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":918,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38556,"lbm_writes_lt_1ms":866,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":12160,"update_count":1545}
I20260812 06:17:25.914124  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling LogGCOp(76d3cd9fa1d6409ab814468522197b46): free 20743880 bytes of WAL
I20260812 06:17:25.914413  9122 log_reader.cc:385] T 76d3cd9fa1d6409ab814468522197b46: removed 2 log segments from log reader
I20260812 06:17:25.914475  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000001 (ops 1-6)
I20260812 06:17:25.914518  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000002 (ops 7-11)
I20260812 06:17:25.919384  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: LogGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:25.919770  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46): 20513813 bytes on disk
I20260812 06:17:25.920174  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:25.920571  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:25.933820  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4779,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:17:25.934276  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:26.072346  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.138s	user 0.082s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":55,"lbm_read_time_us":10503,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21307,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":270,"threads_started":5,"update_count":2000}
I20260812 06:17:26.072940  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:26.109985  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.037s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12053,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.110612  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:26.126739  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6206,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.127322  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:26.291576  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.164s	user 0.098s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":12000,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24994,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:17:26.292196  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=14.095187
I20260812 06:17:26.349298  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.057s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21417,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.349778  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:26.359789  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3556,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.360364  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:26.532245  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.172s	user 0.126s	sys 0.037s 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":333,"lbm_read_time_us":11114,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28044,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:26.532752  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:26.567766  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.035s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14423,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:26.568341  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:26.580351  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4007,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.580896  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:26.706090  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.125s	user 0.084s	sys 0.038s 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":905,"dirs.run_cpu_time_us":533,"dirs.run_wall_time_us":3107,"lbm_read_time_us":8899,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21367,"lbm_writes_lt_1ms":443,"mutex_wait_us":122,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:26.706844  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:26.747262  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.040s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15578,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.747807  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:26.757936  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.758428  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:26.885251  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.127s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":9646,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22021,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:26.885808  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:26.944780  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.059s	user 0.021s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16675,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.945421  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:26.955650  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.956074  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:27.105386  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.149s	user 0.093s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":10740,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24381,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:27.105983  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:27.146348  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.040s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.146855  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:27.157739  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.158183  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushMRSOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:27.186101  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushMRSOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1449,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:27.186748  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling LogGCOp(76d3cd9fa1d6409ab814468522197b46): free 124710241 bytes of WAL
I20260812 06:17:27.186964  9122 log_reader.cc:385] T 76d3cd9fa1d6409ab814468522197b46: removed 12 log segments from log reader
I20260812 06:17:27.187019  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000003 (ops 12-16)
I20260812 06:17:27.187055  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000004 (ops 17-21)
I20260812 06:17:27.187080  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000005 (ops 22-26)
I20260812 06:17:27.187111  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000006 (ops 27-31)
I20260812 06:17:27.187143  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000007 (ops 32-36)
I20260812 06:17:27.187173  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000008 (ops 37-41)
I20260812 06:17:27.187203  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000009 (ops 42-46)
I20260812 06:17:27.187233  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000010 (ops 47-51)
I20260812 06:17:27.187263  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000011 (ops 52-56)
I20260812 06:17:27.187294  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000012 (ops 57-61)
I20260812 06:17:27.187323  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000013 (ops 62-66)
I20260812 06:17:27.187353  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000014 (ops 67-71)
I20260812 06:17:27.210651  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: LogGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:27.211028  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46): 462 bytes on disk
I20260812 06:17:27.211465  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46) 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:27.211925  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=3.181125
I20260812 06:17:27.225876  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:27.226347  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:27.243829  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3269,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.244354  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:27.434037  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.190s	user 0.117s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1053,"lbm_read_time_us":13062,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32637,"lbm_writes_lt_1ms":643,"mutex_wait_us":236,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:27.434548  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=14.095187
I20260812 06:17:27.485632  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.051s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.486147  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:27.496556  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.496985  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:27.665642  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.168s	user 0.125s	sys 0.040s 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":922,"lbm_read_time_us":12034,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26071,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:17:27.666110  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:27.701756  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14990,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1550}
I20260812 06:17:27.702369  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:27.717410  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5242,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":450}
I20260812 06:17:27.717882  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:27.837121  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.119s	user 0.089s	sys 0.027s 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":252,"lbm_read_time_us":7021,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22564,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:17:27.837842  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:27.867090  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.029s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11765,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:27.867668  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:27.884604  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6311,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.885265  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.012547  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.127s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23074,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:17:28.013082  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:28.051256  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.038s	user 0.012s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.051805  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.066833  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5411,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.067416  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.188180  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.121s	user 0.081s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":8172,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22808,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:28.188681  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:28.238620  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.050s	user 0.020s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12930,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.239277  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.249748  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.250226  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.394404  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.144s	user 0.108s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":893,"lbm_read_time_us":10328,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22594,"lbm_writes_lt_1ms":443,"mutex_wait_us":257,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:17:28.395015  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:28.436769  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.042s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.437350  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.447480  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.448173  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.570442  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.122s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1356,"lbm_read_time_us":9389,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23567,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:17:28.571038  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=10.126437
I20260812 06:17:28.606633  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.035s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12349,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:28.607228  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.622398  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.622961  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushMRSOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.650244  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushMRSOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.027s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1325,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1474,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:28.651042  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling LogGCOp(76d3cd9fa1d6409ab814468522197b46): free 121006496 bytes of WAL
I20260812 06:17:28.651314  9122 log_reader.cc:385] T 76d3cd9fa1d6409ab814468522197b46: removed 12 log segments from log reader
I20260812 06:17:28.651365  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000015 (ops 72-76)
I20260812 06:17:28.651412  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000016 (ops 77-81)
I20260812 06:17:28.651446  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000017 (ops 82-86)
I20260812 06:17:28.651481  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000018 (ops 87-91)
I20260812 06:17:28.651510  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000019 (ops 92-96)
I20260812 06:17:28.651533  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000020 (ops 97-101)
I20260812 06:17:28.651557  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000021 (ops 102-106)
I20260812 06:17:28.651588  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000022 (ops 107-111)
I20260812 06:17:28.651618  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000023 (ops 112-116)
I20260812 06:17:28.651649  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000024 (ops 117-120)
I20260812 06:17:28.651679  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000025 (ops 121-125)
I20260812 06:17:28.651710  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000026 (ops 126-130)
I20260812 06:17:28.672200  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: LogGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:28.672761  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46): 483 bytes on disk
I20260812 06:17:28.673200  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46) 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:28.673841  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.687394  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.013s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:17:28.687793  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.702075  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5338,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:28.702584  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:28.870822  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.168s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":566,"lbm_read_time_us":13003,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31463,"lbm_writes_lt_1ms":643,"mutex_wait_us":84,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:28.871384  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=14.095187
I20260812 06:17:28.919823  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.048s	user 0.038s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18786,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.920360  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:28.935727  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.936336  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:29.093932  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.157s	user 0.133s	sys 0.015s 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":165,"lbm_read_time_us":9491,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28042,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:29.094564  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=14.095187
I20260812 06:17:29.140256  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.045s	user 0.022s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20530,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.140843  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:29.275480  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.134s	user 0.087s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":191,"lbm_read_time_us":8945,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23187,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:29.276098  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:29.311728  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14531,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.312377  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.335246  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.023s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5019,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.335732  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.345623  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.346091  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:29.512545  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.166s	user 0.124s	sys 0.033s 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":166,"lbm_read_time_us":8936,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25982,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:29.513165  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=14.095187
I20260812 06:17:29.563582  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.050s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18279,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.564162  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.575086  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3939,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.575541  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:29.728943  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.153s	user 0.122s	sys 0.026s 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":1107,"lbm_read_time_us":9214,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30198,"lbm_writes_lt_1ms":543,"mutex_wait_us":518,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:29.729533  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:29.764634  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.035s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14258,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.765192  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.788081  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.023s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.788594  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.798560  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3670,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.799172  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:29.932401  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.133s	user 0.110s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":287,"lbm_read_time_us":8204,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26638,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:17:29.933214  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=11.118625
I20260812 06:17:29.961793  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.028s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11657,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.962555  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:29.977083  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.977692  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushMRSOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:30.035598  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushMRSOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.058s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1311,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1621,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:30.036427  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling LogGCOp(76d3cd9fa1d6409ab814468522197b46): free 124710566 bytes of WAL
I20260812 06:17:30.036708  9122 log_reader.cc:385] T 76d3cd9fa1d6409ab814468522197b46: removed 12 log segments from log reader
I20260812 06:17:30.036824  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000027 (ops 131-135)
I20260812 06:17:30.036886  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000028 (ops 136-140)
I20260812 06:17:30.036927  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000029 (ops 141-145)
I20260812 06:17:30.036963  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000030 (ops 146-150)
I20260812 06:17:30.037001  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000031 (ops 151-155)
I20260812 06:17:30.037043  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000032 (ops 156-160)
I20260812 06:17:30.037079  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000033 (ops 161-165)
I20260812 06:17:30.037117  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000034 (ops 166-170)
I20260812 06:17:30.037153  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000035 (ops 171-175)
I20260812 06:17:30.037189  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000036 (ops 176-180)
I20260812 06:17:30.037223  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000037 (ops 181-185)
I20260812 06:17:30.037259  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000038 (ops 186-190)
I20260812 06:17:30.060050  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: LogGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.023s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:30.060537  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46): 482 bytes on disk
I20260812 06:17:30.061136  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: UndoDeltaBlockGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.061734  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=7.149875
I20260812 06:17:30.090006  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12380,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:30.090768  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling LogGCOp(76d3cd9fa1d6409ab814468522197b46): free 12017897 bytes of WAL
I20260812 06:17:30.091125  9122 log_reader.cc:385] T 76d3cd9fa1d6409ab814468522197b46: removed 1 log segments from log reader
I20260812 06:17:30.091194  9122 log.cc:1079] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: Deleting log segment in path: /tmp/dist-test-taskLxWCf5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515440138029-8592-0/minicluster-data/ts-0-root/wals/76d3cd9fa1d6409ab814468522197b46/wal-000000039 (ops 191-195)
I20260812 06:17:30.093757  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: LogGCOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:30.094270  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46): perf score=2.188937
I20260812 06:17:30.113633  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: FlushDeltaMemStoresOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.019s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.114244  9225 maintenance_manager.cc:419] P 14d44795d61a4cc391b662407e1ee3f7: Scheduling MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46): perf score=1.000000
I20260812 06:17:30.193688  8592 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.595s	user 1.638s	sys 0.176s
I20260812 06:17:30.293942  8592 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.100s	user 0.003s	sys 0.000s
I20260812 06:17:30.294499  8592 tablet_server.cc:179] TabletServer@127.8.100.1:0 shutting down...
I20260812 06:17:30.321274  9122 maintenance_manager.cc:643] P 14d44795d61a4cc391b662407e1ee3f7: MajorDeltaCompactionOp(76d3cd9fa1d6409ab814468522197b46) complete. Timing: real 0.207s	user 0.142s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020729,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":417,"lbm_read_time_us":16230,"lbm_reads_lt_1ms":762,"lbm_write_time_us":31663,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20864,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:17:30.321988  8592 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:30.322311  8592 tablet_replica.cc:333] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7: stopping tablet replica
I20260812 06:17:30.322445  8592 raft_consensus.cc:2243] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.322594  8592 raft_consensus.cc:2272] T 76d3cd9fa1d6409ab814468522197b46 P 14d44795d61a4cc391b662407e1ee3f7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.337369  8592 tablet_server.cc:196] TabletServer@127.8.100.1:0 shutdown complete.
I20260812 06:17:30.379469  8592 master.cc:562] Master@127.8.100.62:34281 shutting down...
I20260812 06:17:30.382583  8592 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.382758  8592 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.382830  8592 tablet_replica.cc:333] T 00000000000000000000000000000000 P 72ab08a773e24ff6a9de6c9c3d5eb0d4: stopping tablet replica
I20260812 06:17:30.394918  8592 master.cc:584] Master@127.8.100.62:34281 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5032 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10317 ms total)

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