[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:42.047021 14253 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.235.126:39907
I20260812 06:19:42.048171 14253 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:42.048872 14253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.056007 14259 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.056093 14253 server_base.cc:1061] running on GCE node
W20260812 06:19:42.056030 14261 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.056329 14258 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.056900 14253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.057000 14253 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.057082 14253 hybrid_clock.cc:648] HybridClock initialized: now 1786515582057079 us; error 0 us; skew 500 ppm
I20260812 06:19:42.059185 14253 webserver.cc:533] Webserver started at http://127.13.235.126:45019/ using document root <none> and password file <none>
I20260812 06:19:42.059825 14253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.059894 14253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.060178 14253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.062145 14253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/master-0-root/instance:
uuid: "a22bf2e9f793451dba1d5722f1646803"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-vxj2"
I20260812 06:19:42.066599 14253 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:19:42.069965 14266 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.071517 14253 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:42.071718 14253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/master-0-root
uuid: "a22bf2e9f793451dba1d5722f1646803"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-vxj2"
I20260812 06:19:42.071862 14253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.086836 14253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.087630 14253 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:42.087843 14253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.096630 14338 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.235.126:39907 every 8 connection(s)
I20260812 06:19:42.096630 14253 rpc_server.cc:307] RPC server started. Bound to: 127.13.235.126:39907
I20260812 06:19:42.099292 14339 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.105772 14339 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: Bootstrap starting.
I20260812 06:19:42.108839 14339 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.110064 14339 log.cc:826] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:42.112246 14339 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: No bootstrap required, opened a new log
I20260812 06:19:42.115592 14339 raft_consensus.cc:359] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER }
I20260812 06:19:42.115813 14339 raft_consensus.cc:385] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.115859 14339 raft_consensus.cc:740] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a22bf2e9f793451dba1d5722f1646803, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.116463 14339 consensus_queue.cc:260] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [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: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER }
I20260812 06:19:42.116618 14339 raft_consensus.cc:399] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.116665 14339 raft_consensus.cc:493] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.116757 14339 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.117787 14339 raft_consensus.cc:515] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER }
I20260812 06:19:42.118253 14339 leader_election.cc:304] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [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: a22bf2e9f793451dba1d5722f1646803; no voters: 
I20260812 06:19:42.118573 14339 leader_election.cc:290] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.118980 14343 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.119238 14343 raft_consensus.cc:697] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 1 LEADER]: Becoming Leader. State: Replica: a22bf2e9f793451dba1d5722f1646803, State: Running, Role: LEADER
I20260812 06:19:42.119694 14343 consensus_queue.cc:237] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [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: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER }
I20260812 06:19:42.119735 14339 sys_catalog.cc:565] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:42.122037 14344 sys_catalog.cc:455] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a22bf2e9f793451dba1d5722f1646803" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER } }
I20260812 06:19:42.122207 14344 sys_catalog.cc:458] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.122022 14345 sys_catalog.cc:455] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a22bf2e9f793451dba1d5722f1646803. Latest consensus state: current_term: 1 leader_uuid: "a22bf2e9f793451dba1d5722f1646803" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a22bf2e9f793451dba1d5722f1646803" member_type: VOTER } }
I20260812 06:19:42.122490 14345 sys_catalog.cc:458] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.122534 14253 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:42.124624 14360 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:42.124698 14360 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:42.124781 14359 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:42.125648 14359 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:42.131560 14359 catalog_manager.cc:1383] Generated new cluster ID: b994e56065764867b754ee873acd5be1
I20260812 06:19:42.131664 14359 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:42.153053 14359 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:42.154124 14359 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:42.161866 14359 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: Generated new TSK 0
I20260812 06:19:42.162706 14359 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:42.187777 14253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.191190 14365 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.191390 14366 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:19:42.191692 14368 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.191835 14253 server_base.cc:1061] running on GCE node
I20260812 06:19:42.192149 14253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.192212 14253 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.192237 14253 hybrid_clock.cc:648] HybridClock initialized: now 1786515582192236 us; error 0 us; skew 500 ppm
I20260812 06:19:42.193603 14253 webserver.cc:533] Webserver started at http://127.13.235.65:43987/ using document root <none> and password file <none>
I20260812 06:19:42.193792 14253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.193856 14253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.193929 14253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.194401 14253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/instance:
uuid: "bf86c703297a4911adf50904789015bb"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-vxj2"
I20260812 06:19:42.196343 14253 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:42.197767 14373 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.198143 14253 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:42.198262 14253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root
uuid: "bf86c703297a4911adf50904789015bb"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-vxj2"
I20260812 06:19:42.198369 14253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.209584 14253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.210122 14253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.210816 14253 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:42.211913 14253 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:42.212002 14253 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.212085 14253 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:42.212138 14253 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.219720 14253 rpc_server.cc:307] RPC server started. Bound to: 127.13.235.65:45861
I20260812 06:19:42.219733 14446 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.235.65:45861 every 8 connection(s)
I20260812 06:19:42.238044 14447 heartbeater.cc:344] Connected to a master server at 127.13.235.126:39907
I20260812 06:19:42.238366 14447 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.239033 14447 heartbeater.cc:507] Master 127.13.235.126:39907 requested a full tablet report, sending...
I20260812 06:19:42.240913 14287 ts_manager.cc:194] Registered new tserver with Master: bf86c703297a4911adf50904789015bb (127.13.235.65:45861)
I20260812 06:19:42.241285 14253 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020764892s
I20260812 06:19:42.242631 14287 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40326
I20260812 06:19:42.253072 14287 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40342:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:42.271839 14410 tablet_service.cc:1511] Processing CreateTablet for tablet 890e3bad4c324c8fa2addf7085f9ccbf (DEFAULT_TABLE table=heavy-update-compaction-test [id=c6639ad9318e4a11bef1a8598fab6614]), partition=
I20260812 06:19:42.272480 14410 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 890e3bad4c324c8fa2addf7085f9ccbf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.276432 14462 tablet_bootstrap.cc:492] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Bootstrap starting.
I20260812 06:19:42.277719 14462 tablet_bootstrap.cc:654] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.279605 14462 tablet_bootstrap.cc:492] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: No bootstrap required, opened a new log
I20260812 06:19:42.279757 14462 ts_tablet_manager.cc:1403] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:42.280304 14462 raft_consensus.cc:359] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf86c703297a4911adf50904789015bb" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 45861 } }
I20260812 06:19:42.280459 14462 raft_consensus.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.280512 14462 raft_consensus.cc:740] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bf86c703297a4911adf50904789015bb, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.280676 14462 consensus_queue.cc:260] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [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: "bf86c703297a4911adf50904789015bb" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 45861 } }
I20260812 06:19:42.280781 14462 raft_consensus.cc:399] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.280831 14462 raft_consensus.cc:493] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.280893 14462 raft_consensus.cc:3060] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.281798 14462 raft_consensus.cc:515] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf86c703297a4911adf50904789015bb" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 45861 } }
I20260812 06:19:42.281983 14462 leader_election.cc:304] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [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: bf86c703297a4911adf50904789015bb; no voters: 
I20260812 06:19:42.282245 14462 leader_election.cc:290] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.282370 14467 raft_consensus.cc:2804] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.282559 14467 raft_consensus.cc:697] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 1 LEADER]: Becoming Leader. State: Replica: bf86c703297a4911adf50904789015bb, State: Running, Role: LEADER
I20260812 06:19:42.282655 14462 ts_tablet_manager.cc:1434] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:42.282730 14467 consensus_queue.cc:237] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [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: "bf86c703297a4911adf50904789015bb" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 45861 } }
I20260812 06:19:42.283120 14447 heartbeater.cc:499] Master 127.13.235.126:39907 was elected leader, sending a full tablet report...
I20260812 06:19:42.287041 14287 catalog_manager.cc:5719] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb reported cstate change: term changed from 0 to 1, leader changed from <none> to bf86c703297a4911adf50904789015bb (127.13.235.65). New cstate: current_term: 1 leader_uuid: "bf86c703297a4911adf50904789015bb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bf86c703297a4911adf50904789015bb" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 45861 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.352494 14253 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.005s
I20260812 06:19:42.471273 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=15.086190
I20260812 06:19:42.633617 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.162s	user 0.115s	sys 0.043s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":249,"delete_count":0,"dirs.queue_time_us":147,"dirs.run_cpu_time_us":338,"dirs.run_wall_time_us":1220,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36544,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":141,"threads_started":1,"update_count":1000}
I20260812 06:19:42.634990 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 11976772 bytes of WAL
I20260812 06:19:42.635480 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 1 log segments from log reader
I20260812 06:19:42.635591 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000001 (ops 1-6)
I20260812 06:19:42.638454 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:42.638950 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:42.659021 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.659595 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:42.785508 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.126s	user 0.105s	sys 0.017s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528900,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1265,"lbm_read_time_us":6862,"lbm_reads_lt_1ms":368,"lbm_write_time_us":21853,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":373,"threads_started":5,"update_count":1500}
I20260812 06:19:42.786131 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=7.149875
I20260812 06:19:42.814780 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.028s	user 0.016s	sys 0.011s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12048,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:42.815426 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:42.828279 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.828816 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:42.957418 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.128s	user 0.090s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1254,"lbm_read_time_us":7989,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20762,"lbm_writes_lt_1ms":343,"mutex_wait_us":432,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":1500}
I20260812 06:19:42.957984 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf): 12308959 bytes on disk
I20260812 06:19:42.958580 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.959067 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:43.016677 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.057s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20723,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.017395 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:43.029313 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.030133 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:43.167376 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.137s	user 0.118s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":802,"lbm_read_time_us":10221,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25708,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:19:43.168037 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:43.213950 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.046s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17139,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.214618 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:43.227468 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.228067 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:43.356201 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.128s	user 0.101s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1116,"lbm_read_time_us":9565,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24376,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:43.356781 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:43.402366 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.045s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17577,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.403033 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:43.414465 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.415279 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:43.550038 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.135s	user 0.091s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":914,"lbm_read_time_us":9822,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26018,"lbm_writes_lt_1ms":443,"mutex_wait_us":342,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:43.550652 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:43.605101 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.054s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18484,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.605782 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:43.617918 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.618507 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:43.779374 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.161s	user 0.095s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":11995,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26188,"lbm_writes_lt_1ms":443,"mutex_wait_us":270,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:43.780009 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:43.824643 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.044s	user 0.014s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17565,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.825307 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:43.837199 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.837949 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:43.965610 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.127s	user 0.098s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":9203,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23693,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:19:43.966262 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:44.013270 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.047s	user 0.022s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22568,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.013856 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:44.028158 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.028909 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:44.063728 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1533,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:44.064643 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 121459483 bytes of WAL
I20260812 06:19:44.064913 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 12 log segments from log reader
I20260812 06:19:44.064967 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000002 (ops 7-11)
I20260812 06:19:44.065026 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000003 (ops 12-16)
I20260812 06:19:44.065076 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000004 (ops 17-21)
I20260812 06:19:44.065127 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000005 (ops 22-26)
I20260812 06:19:44.065219 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000006 (ops 27-31)
I20260812 06:19:44.065280 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000007 (ops 32-36)
I20260812 06:19:44.065320 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000008 (ops 37-41)
I20260812 06:19:44.065367 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000009 (ops 42-46)
I20260812 06:19:44.065418 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000010 (ops 47-51)
I20260812 06:19:44.065457 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000011 (ops 52-56)
I20260812 06:19:44.065495 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000012 (ops 57-61)
I20260812 06:19:44.065534 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000013 (ops 62-66)
I20260812 06:19:44.094848 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:19:44.095464 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=6.157687
I20260812 06:19:44.116132 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":7384594,"delete_count":0,"lbm_write_time_us":8074,"lbm_writes_lt_1ms":183,"reinsert_count":0,"update_count":900}
I20260812 06:19:44.118901 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 11564875 bytes of WAL
I20260812 06:19:44.119197 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 1 log segments from log reader
I20260812 06:19:44.119244 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000014 (ops 67-70)
I20260812 06:19:44.122308 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:44.122673 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:44.308805 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.186s	user 0.154s	sys 0.021s Metrics: {"cfile_cache_miss":613,"cfile_cache_miss_bytes":28015772,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":261,"lbm_read_time_us":12512,"lbm_reads_lt_1ms":645,"lbm_write_time_us":37003,"lbm_writes_lt_1ms":623,"mutex_wait_us":24,"peak_mem_usage":72641004,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":86,"threads_started":1,"update_count":2900}
I20260812 06:19:44.309540 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf): 473 bytes on disk
I20260812 06:19:44.310109 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.310810 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=15.087375
I20260812 06:19:44.365474 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.054s	user 0.032s	sys 0.019s Metrics: {"bytes_written":17230392,"delete_count":0,"lbm_write_time_us":22903,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:19:44.365990 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:44.377543 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.378172 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:44.551630 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.173s	user 0.114s	sys 0.055s Metrics: {"cfile_cache_miss":552,"cfile_cache_miss_bytes":25554213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":11773,"lbm_reads_lt_1ms":592,"lbm_write_time_us":35839,"lbm_writes_lt_1ms":563,"mutex_wait_us":64,"peak_mem_usage":64976984,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2600}
I20260812 06:19:44.552469 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=11.118625
I20260812 06:19:44.594332 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.042s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17674,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.594901 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:44.611569 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5712,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.612181 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:44.752390 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.140s	user 0.094s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":11160,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24746,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:44.753300 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:44.799819 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15724,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.800617 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:44.814929 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.815500 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:44.961512 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.146s	user 0.108s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":10149,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24928,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.965569 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:45.006819 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18121,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.007508 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:45.020393 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.013s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.021005 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.151564 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.130s	user 0.100s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":9992,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25901,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.152359 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:45.195480 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.043s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15245,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":1500}
I20260812 06:19:45.196141 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:45.212285 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.212860 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.355768 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.143s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":289,"lbm_read_time_us":9299,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29218,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:19:45.356743 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:45.416543 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.060s	user 0.020s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20124,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.417348 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:45.430820 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.431411 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.601693 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.170s	user 0.118s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":12901,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27204,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:19:45.602286 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:45.651706 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.049s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17997,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.652311 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:45.664383 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.664938 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.703994 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1485,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1806,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:45.704873 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 116849471 bytes of WAL
I20260812 06:19:45.705225 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 12 log segments from log reader
I20260812 06:19:45.705297 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000015 (ops 71-75)
I20260812 06:19:45.705338 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000016 (ops 76-80)
I20260812 06:19:45.705374 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000017 (ops 81-84)
I20260812 06:19:45.705408 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000018 (ops 85-89)
I20260812 06:19:45.705441 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000019 (ops 90-94)
I20260812 06:19:45.705463 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000020 (ops 95-98)
I20260812 06:19:45.705493 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000021 (ops 99-103)
I20260812 06:19:45.705524 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000022 (ops 104-108)
I20260812 06:19:45.705557 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000023 (ops 109-113)
I20260812 06:19:45.705591 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000024 (ops 114-118)
I20260812 06:19:45.705622 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000025 (ops 119-122)
I20260812 06:19:45.705653 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000026 (ops 123-127)
I20260812 06:19:45.735394 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.030s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:19:45.735966 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf): 482 bytes on disk
I20260812 06:19:45.736678 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.737682 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=5.165500
I20260812 06:19:45.763856 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.026s	user 0.010s	sys 0.013s Metrics: {"bytes_written":7015375,"delete_count":0,"lbm_write_time_us":7185,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:19:45.764732 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 12018000 bytes of WAL
I20260812 06:19:45.765061 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 1 log segments from log reader
I20260812 06:19:45.765125 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000027 (ops 128-132)
I20260812 06:19:45.768780 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:45.769268 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.778223 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.009s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":2087,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:19:45.778738 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:45.982482 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.204s	user 0.139s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836305,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":888,"lbm_read_time_us":13895,"lbm_reads_lt_1ms":670,"lbm_write_time_us":35427,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:45.983343 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=14.095187
I20260812 06:19:46.045833 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.062s	user 0.026s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.046638 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:46.058674 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.059242 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:46.237965 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.179s	user 0.138s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1284,"lbm_read_time_us":12968,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29293,"lbm_writes_lt_1ms":543,"mutex_wait_us":369,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:19:46.238514 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:46.277452 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.039s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16228,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.278057 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:46.292917 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5544,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.293478 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:46.449362 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.156s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":477,"lbm_read_time_us":10793,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26603,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:46.450290 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:46.491199 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.041s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15544,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:19:46.491782 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:46.502955 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.503489 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:46.646384 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.143s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":763,"lbm_read_time_us":9483,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28108,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:46.647208 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:46.686363 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.039s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15710,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.686942 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:46.798678 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.112s	user 0.089s	sys 0.023s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":202,"lbm_read_time_us":6419,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22794,"lbm_writes_lt_1ms":343,"mutex_wait_us":46,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":1500}
I20260812 06:19:46.799484 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:46.844051 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.044s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15227,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.844602 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:46.855926 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.856830 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:47.001888 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.145s	user 0.109s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":348,"lbm_read_time_us":10258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26787,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:47.002596 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:47.053148 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.050s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.053802 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:47.065734 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.066253 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:47.207032 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.141s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1299,"lbm_read_time_us":10031,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28724,"lbm_writes_lt_1ms":443,"mutex_wait_us":353,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:47.207695 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=10.126437
I20260812 06:19:47.260176 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.052s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18398,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.260773 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=2.188937
I20260812 06:19:47.272728 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.273362 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:47.304648 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushMRSOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1581,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1677,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:47.305414 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf): free 121006699 bytes of WAL
I20260812 06:19:47.305642 14378 log_reader.cc:385] T 890e3bad4c324c8fa2addf7085f9ccbf: removed 12 log segments from log reader
I20260812 06:19:47.305686 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000028 (ops 133-137)
I20260812 06:19:47.305732 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000029 (ops 138-142)
I20260812 06:19:47.305776 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000030 (ops 143-146)
I20260812 06:19:47.305816 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000031 (ops 147-151)
I20260812 06:19:47.305857 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000032 (ops 152-156)
I20260812 06:19:47.305903 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000033 (ops 157-161)
I20260812 06:19:47.305946 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000034 (ops 162-166)
I20260812 06:19:47.305987 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000035 (ops 167-171)
I20260812 06:19:47.306026 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000036 (ops 172-176)
I20260812 06:19:47.306066 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000037 (ops 177-181)
I20260812 06:19:47.306106 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000038 (ops 182-186)
I20260812 06:19:47.306145 14378 log.cc:1079] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/890e3bad4c324c8fa2addf7085f9ccbf/wal-000000039 (ops 187-191)
I20260812 06:19:47.332077 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: LogGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:47.332543 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf): 473 bytes on disk
I20260812 06:19:47.333104 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: UndoDeltaBlockGCOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.333688 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=4.173312
I20260812 06:19:47.349943 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":5374416,"delete_count":0,"lbm_write_time_us":6220,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:19:47.350565 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.196750
I20260812 06:19:47.363343 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:47.364029 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=1.000000
I20260812 06:19:47.546429 14253 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.194s	user 1.899s	sys 0.092s
I20260812 06:19:47.549248 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: MajorDeltaCompactionOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.185s	user 0.128s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":143,"lbm_read_time_us":12997,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36359,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:19:47.553576 14448 maintenance_manager.cc:419] P bf86c703297a4911adf50904789015bb: Scheduling FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf): perf score=14.095187
I20260812 06:19:47.581308 14253 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.034s	user 0.004s	sys 0.000s
I20260812 06:19:47.582022 14253 tablet_server.cc:179] TabletServer@127.13.235.65:0 shutting down...
I20260812 06:19:47.606647 14378 maintenance_manager.cc:643] P bf86c703297a4911adf50904789015bb: FlushDeltaMemStoresOp(890e3bad4c324c8fa2addf7085f9ccbf) complete. Timing: real 0.053s	user 0.020s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.607296 14253 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.607750 14253 tablet_replica.cc:333] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb: stopping tablet replica
I20260812 06:19:47.607960 14253 raft_consensus.cc:2243] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.608160 14253 raft_consensus.cc:2272] T 890e3bad4c324c8fa2addf7085f9ccbf P bf86c703297a4911adf50904789015bb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.623373 14253 tablet_server.cc:196] TabletServer@127.13.235.65:0 shutdown complete.
I20260812 06:19:47.629011 14253 master.cc:562] Master@127.13.235.126:39907 shutting down...
I20260812 06:19:47.633845 14253 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.634069 14253 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.634135 14253 tablet_replica.cc:333] T 00000000000000000000000000000000 P a22bf2e9f793451dba1d5722f1646803: stopping tablet replica
I20260812 06:19:47.646713 14253 master.cc:584] Master@127.13.235.126:39907 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5693 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:47.739795 14253 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.235.126:39607
I20260812 06:19:47.740206 14253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.742875 14491 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:19:47.743000 14494 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.743062 14253 server_base.cc:1061] running on GCE node
W20260812 06:19:47.742966 14490 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.743414 14253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.743460 14253 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.743476 14253 hybrid_clock.cc:648] HybridClock initialized: now 1786515587743476 us; error 0 us; skew 500 ppm
I20260812 06:19:47.744459 14253 webserver.cc:533] Webserver started at http://127.13.235.126:44247/ using document root <none> and password file <none>
I20260812 06:19:47.744647 14253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.744696 14253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.744774 14253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.745298 14253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/master-0-root/instance:
uuid: "2feceb2af91242c0ac728cc603294b6c"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-vxj2"
I20260812 06:19:47.747045 14253 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:19:47.748112 14501 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.748409 14253 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:47.748504 14253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/master-0-root
uuid: "2feceb2af91242c0ac728cc603294b6c"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-vxj2"
I20260812 06:19:47.748595 14253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.763358 14253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.763818 14253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.769264 14253 rpc_server.cc:307] RPC server started. Bound to: 127.13.235.126:39607
I20260812 06:19:47.772346 14572 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.776445 14571 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.235.126:39607 every 8 connection(s)
I20260812 06:19:47.787925 14572 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c: Bootstrap starting.
I20260812 06:19:47.788858 14572 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.790163 14572 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c: No bootstrap required, opened a new log
I20260812 06:19:47.790606 14572 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER }
I20260812 06:19:47.790709 14572 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.790731 14572 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2feceb2af91242c0ac728cc603294b6c, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.790900 14572 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [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: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER }
I20260812 06:19:47.791000 14572 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.791026 14572 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.791062 14572 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.791841 14572 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER }
I20260812 06:19:47.791983 14572 leader_election.cc:304] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [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: 2feceb2af91242c0ac728cc603294b6c; no voters: 
I20260812 06:19:47.792177 14572 leader_election.cc:290] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.792371 14575 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.792603 14575 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 1 LEADER]: Becoming Leader. State: Replica: 2feceb2af91242c0ac728cc603294b6c, State: Running, Role: LEADER
I20260812 06:19:47.792747 14572 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:47.792770 14575 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [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: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER }
I20260812 06:19:47.793314 14576 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2feceb2af91242c0ac728cc603294b6c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER } }
I20260812 06:19:47.793310 14577 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2feceb2af91242c0ac728cc603294b6c. Latest consensus state: current_term: 1 leader_uuid: "2feceb2af91242c0ac728cc603294b6c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2feceb2af91242c0ac728cc603294b6c" member_type: VOTER } }
I20260812 06:19:47.793443 14577 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.793681 14576 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.794080 14581 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:47.795194 14581 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:47.795429 14253 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:47.797225 14581 catalog_manager.cc:1383] Generated new cluster ID: fd4a7ca184174c238ff414f1bce347ac
I20260812 06:19:47.797289 14581 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:47.804234 14581 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:47.804850 14581 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:47.811528 14581 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c: Generated new TSK 0
I20260812 06:19:47.811745 14581 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:47.827999 14253 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.830451 14601 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.830533 14253 server_base.cc:1061] running on GCE node
W20260812 06:19:47.830569 14596 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.830466 14599 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.830924 14253 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.831003 14253 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.831020 14253 hybrid_clock.cc:648] HybridClock initialized: now 1786515587831020 us; error 0 us; skew 500 ppm
I20260812 06:19:47.831979 14253 webserver.cc:533] Webserver started at http://127.13.235.65:33213/ using document root <none> and password file <none>
I20260812 06:19:47.832136 14253 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.832182 14253 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.832239 14253 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.832628 14253 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/instance:
uuid: "f87f4982fe40473fb7723dede60d7d26"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-vxj2"
I20260812 06:19:47.834350 14253 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:47.835395 14606 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.835700 14253 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:47.835799 14253 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root
uuid: "f87f4982fe40473fb7723dede60d7d26"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-vxj2"
I20260812 06:19:47.835893 14253 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.846052 14253 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.846511 14253 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.846871 14253 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:47.847437 14253 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:47.847491 14253 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.847550 14253 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:47.847594 14253 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.852201 14253 rpc_server.cc:307] RPC server started. Bound to: 127.13.235.65:35703
I20260812 06:19:47.852245 14684 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.235.65:35703 every 8 connection(s)
I20260812 06:19:47.862869 14685 heartbeater.cc:344] Connected to a master server at 127.13.235.126:39607
I20260812 06:19:47.863015 14685 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:47.863255 14685 heartbeater.cc:507] Master 127.13.235.126:39607 requested a full tablet report, sending...
I20260812 06:19:47.863924 14520 ts_manager.cc:194] Registered new tserver with Master: f87f4982fe40473fb7723dede60d7d26 (127.13.235.65:35703)
I20260812 06:19:47.864717 14520 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56216
I20260812 06:19:47.864962 14253 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012298486s
I20260812 06:19:47.872967 14520 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56230:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:47.882967 14643 tablet_service.cc:1511] Processing CreateTablet for tablet 137fa0e68b214053a8455727fb68bda7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c07ba43bea1048e096e650d174a30dd9]), partition=
I20260812 06:19:47.883416 14643 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 137fa0e68b214053a8455727fb68bda7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.885691 14700 tablet_bootstrap.cc:492] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Bootstrap starting.
I20260812 06:19:47.886722 14700 tablet_bootstrap.cc:654] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.888093 14700 tablet_bootstrap.cc:492] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: No bootstrap required, opened a new log
I20260812 06:19:47.888218 14700 ts_tablet_manager.cc:1403] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:47.888741 14700 raft_consensus.cc:359] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f87f4982fe40473fb7723dede60d7d26" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 35703 } }
I20260812 06:19:47.888865 14700 raft_consensus.cc:385] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.888914 14700 raft_consensus.cc:740] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f87f4982fe40473fb7723dede60d7d26, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.889070 14700 consensus_queue.cc:260] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [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: "f87f4982fe40473fb7723dede60d7d26" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 35703 } }
I20260812 06:19:47.889205 14700 raft_consensus.cc:399] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.889264 14700 raft_consensus.cc:493] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.889320 14700 raft_consensus.cc:3060] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.890115 14700 raft_consensus.cc:515] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f87f4982fe40473fb7723dede60d7d26" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 35703 } }
I20260812 06:19:47.890281 14700 leader_election.cc:304] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [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: f87f4982fe40473fb7723dede60d7d26; no voters: 
I20260812 06:19:47.890508 14700 leader_election.cc:290] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.890661 14702 raft_consensus.cc:2804] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.890875 14700 ts_tablet_manager.cc:1434] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:47.890889 14685 heartbeater.cc:499] Master 127.13.235.126:39607 was elected leader, sending a full tablet report...
I20260812 06:19:47.890897 14702 raft_consensus.cc:697] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 1 LEADER]: Becoming Leader. State: Replica: f87f4982fe40473fb7723dede60d7d26, State: Running, Role: LEADER
I20260812 06:19:47.891139 14702 consensus_queue.cc:237] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [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: "f87f4982fe40473fb7723dede60d7d26" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 35703 } }
I20260812 06:19:47.892666 14519 catalog_manager.cc:5719] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 reported cstate change: term changed from 0 to 1, leader changed from <none> to f87f4982fe40473fb7723dede60d7d26 (127.13.235.65). New cstate: current_term: 1 leader_uuid: "f87f4982fe40473fb7723dede60d7d26" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f87f4982fe40473fb7723dede60d7d26" member_type: VOTER last_known_addr { host: "127.13.235.65" port: 35703 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:47.954180 14253 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.004s
I20260812 06:19:48.103237 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushMRSOp(137fa0e68b214053a8455727fb68bda7): perf score=19.054940
I20260812 06:19:48.246289 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushMRSOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.143s	user 0.102s	sys 0.040s Metrics: {"bytes_written":9025564,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1090,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36319,"lbm_writes_lt_1ms":677,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":12160,"update_count":1100}
I20260812 06:19:48.247203 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling LogGCOp(137fa0e68b214053a8455727fb68bda7): free 20743880 bytes of WAL
I20260812 06:19:48.247507 14613 log_reader.cc:385] T 137fa0e68b214053a8455727fb68bda7: removed 2 log segments from log reader
I20260812 06:19:48.247560 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000001 (ops 1-6)
I20260812 06:19:48.247593 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000002 (ops 7-11)
I20260812 06:19:48.252067 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: LogGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:48.252523 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7): 16411393 bytes on disk
I20260812 06:19:48.253072 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7) 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:19:48.253695 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:48.267340 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:48.268008 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:48.389430 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.121s	user 0.109s	sys 0.012s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569847,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1487,"lbm_read_time_us":8340,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22064,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":741,"threads_started":5,"update_count":1500}
I20260812 06:19:48.390167 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=10.126437
I20260812 06:19:48.453850 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.063s	user 0.025s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.454393 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:48.465890 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.466615 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:48.625499 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.159s	user 0.105s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":801,"lbm_read_time_us":11921,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25410,"lbm_writes_lt_1ms":443,"mutex_wait_us":325,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2000}
I20260812 06:19:48.626606 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=10.126437
I20260812 06:19:48.668390 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.042s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18221,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.669008 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:48.688014 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7003,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.688645 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:48.824541 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.136s	user 0.098s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":832,"lbm_read_time_us":10461,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24907,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:48.825310 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=10.126437
I20260812 06:19:48.856204 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.031s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13017,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:19:48.856786 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:48.870828 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.871580 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:49.012064 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.140s	user 0.110s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1119,"lbm_read_time_us":10298,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26556,"lbm_writes_lt_1ms":443,"mutex_wait_us":360,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:19:49.012811 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=10.126437
I20260812 06:19:49.068331 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.055s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20915,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.068948 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.080813 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.081432 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:49.234894 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.153s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":11595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25734,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32896,"update_count":2000}
I20260812 06:19:49.235704 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=10.126437
I20260812 06:19:49.291052 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.055s	user 0.018s	sys 0.035s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20004,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.291919 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.303963 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.304493 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:49.469439 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.165s	user 0.106s	sys 0.053s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":11014,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26495,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:19:49.470223 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=11.118625
I20260812 06:19:49.512046 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.042s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16560,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:49.512662 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.533126 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.533730 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.544203 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3771,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.544780 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushMRSOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:49.578788 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushMRSOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1753,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1492,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:49.579488 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling LogGCOp(137fa0e68b214053a8455727fb68bda7): free 112239262 bytes of WAL
I20260812 06:19:49.579766 14613 log_reader.cc:385] T 137fa0e68b214053a8455727fb68bda7: removed 11 log segments from log reader
I20260812 06:19:49.579830 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000003 (ops 12-16)
I20260812 06:19:49.579871 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000004 (ops 17-21)
I20260812 06:19:49.579902 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000005 (ops 22-26)
I20260812 06:19:49.579945 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000006 (ops 27-31)
I20260812 06:19:49.579972 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000007 (ops 32-36)
I20260812 06:19:49.580003 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000008 (ops 37-40)
I20260812 06:19:49.580029 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000009 (ops 41-45)
I20260812 06:19:49.580060 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000010 (ops 46-50)
I20260812 06:19:49.580087 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000011 (ops 51-55)
I20260812 06:19:49.580118 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000012 (ops 56-60)
I20260812 06:19:49.580147 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000013 (ops 61-65)
I20260812 06:19:49.607241 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: LogGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:49.607777 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7): 447 bytes on disk
I20260812 06:19:49.608408 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.608979 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.625059 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.016s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":500}
I20260812 06:19:49.625721 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:49.842325 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.216s	user 0.141s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":210,"lbm_read_time_us":14449,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37036,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:49.843104 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=18.063937
I20260812 06:19:49.932281 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.089s	user 0.050s	sys 0.035s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":34836,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:49.932952 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.961606 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.028s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5920,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.962149 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:49.977794 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.978490 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:50.245464 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.267s	user 0.173s	sys 0.092s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979632,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":940,"lbm_read_time_us":18506,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42418,"lbm_writes_lt_1ms":743,"mutex_wait_us":415,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3500}
I20260812 06:19:50.246603 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=16.079562
I20260812 06:19:50.297852 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.051s	user 0.023s	sys 0.024s Metrics: {"bytes_written":17804726,"delete_count":0,"lbm_write_time_us":21565,"lbm_writes_lt_1ms":437,"reinsert_count":0,"update_count":2170}
I20260812 06:19:50.301762 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=1.196750
I20260812 06:19:50.320535 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.018s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:19:50.321285 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:50.336483 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.337073 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:50.559024 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.222s	user 0.161s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":13713,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37544,"lbm_writes_lt_1ms":643,"mutex_wait_us":87,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:19:50.559918 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:50.632174 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.072s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25699,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.632799 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:50.645931 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.646536 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:50.840332 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.194s	user 0.123s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":13838,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33183,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:19:50.841090 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:50.910086 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.069s	user 0.042s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27128,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.910748 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:50.923426 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.924110 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:51.096117 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.172s	user 0.097s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":435,"lbm_read_time_us":13010,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29064,"lbm_writes_lt_1ms":543,"mutex_wait_us":181,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:51.096866 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:51.163285 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.066s	user 0.020s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18721,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.164083 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:51.176568 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.177229 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushMRSOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:51.221283 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushMRSOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.044s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1822,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1739,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:51.222090 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling LogGCOp(137fa0e68b214053a8455727fb68bda7): free 121006495 bytes of WAL
I20260812 06:19:51.222378 14613 log_reader.cc:385] T 137fa0e68b214053a8455727fb68bda7: removed 12 log segments from log reader
I20260812 06:19:51.222445 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000014 (ops 66-70)
I20260812 06:19:51.222497 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000015 (ops 71-75)
I20260812 06:19:51.222553 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000016 (ops 76-80)
I20260812 06:19:51.222597 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000017 (ops 81-84)
I20260812 06:19:51.222638 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000018 (ops 85-89)
I20260812 06:19:51.222678 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000019 (ops 90-94)
I20260812 06:19:51.222720 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000020 (ops 95-99)
I20260812 06:19:51.222760 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000021 (ops 100-104)
I20260812 06:19:51.222800 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000022 (ops 105-109)
I20260812 06:19:51.222841 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000023 (ops 110-114)
I20260812 06:19:51.222879 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000024 (ops 115-119)
I20260812 06:19:51.222916 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000025 (ops 120-124)
I20260812 06:19:51.251562 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: LogGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:51.252159 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7): 463 bytes on disk
I20260812 06:19:51.252851 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":119,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.253551 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=3.181125
I20260812 06:19:51.279523 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.026s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6989,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.280086 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:51.290252 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3609,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.290956 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:51.535375 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.244s	user 0.137s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":638,"lbm_read_time_us":16085,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41667,"lbm_writes_lt_1ms":743,"mutex_wait_us":62,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20352,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:51.536176 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=18.063937
I20260812 06:19:51.607007 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.071s	user 0.059s	sys 0.010s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31339,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:51.607635 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:51.624210 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.624732 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:51.805341 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.180s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":11469,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36723,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":35712,"update_count":3000}
I20260812 06:19:51.806167 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:51.864559 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.058s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24724,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.865243 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:51.879582 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.880194 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:52.051100 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.171s	user 0.098s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1192,"lbm_read_time_us":10685,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30200,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":393,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:52.051942 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:52.111793 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.060s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":28968,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.112504 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:52.286372 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.174s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":269,"lbm_read_time_us":10957,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29959,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:19:52.287177 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:52.343465 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.056s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22006,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.344141 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:52.362165 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.363054 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:52.594751 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.231s	user 0.151s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1562,"lbm_read_time_us":14159,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32199,"lbm_writes_lt_1ms":543,"mutex_wait_us":350,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:19:52.600270 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=14.095187
I20260812 06:19:52.657351 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.057s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25556,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.658159 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:52.675233 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.675805 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:52.848018 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.171s	user 0.144s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1124,"lbm_read_time_us":12149,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34673,"lbm_writes_lt_1ms":543,"mutex_wait_us":791,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:52.848868 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=11.118625
I20260812 06:19:52.899996 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.051s	user 0.031s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21390,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:52.900570 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:52.922549 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.022s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.923210 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:52.933966 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3769,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.934501 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushMRSOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:52.971014 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushMRSOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.036s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1652,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2436,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:52.971802 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling LogGCOp(137fa0e68b214053a8455727fb68bda7): free 136728493 bytes of WAL
I20260812 06:19:52.972066 14613 log_reader.cc:385] T 137fa0e68b214053a8455727fb68bda7: removed 13 log segments from log reader
I20260812 06:19:52.972126 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000026 (ops 125-129)
I20260812 06:19:52.972157 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000027 (ops 130-134)
I20260812 06:19:52.972175 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000028 (ops 135-139)
I20260812 06:19:52.972236 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000029 (ops 140-144)
I20260812 06:19:52.972285 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000030 (ops 145-149)
I20260812 06:19:52.972312 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000031 (ops 150-154)
I20260812 06:19:52.972329 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000032 (ops 155-159)
I20260812 06:19:52.972345 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000033 (ops 160-164)
I20260812 06:19:52.972361 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000034 (ops 165-169)
I20260812 06:19:52.972378 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000035 (ops 170-174)
I20260812 06:19:52.972393 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000036 (ops 175-179)
I20260812 06:19:52.972410 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000037 (ops 180-184)
I20260812 06:19:52.972430 14613 log.cc:1079] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: Deleting log segment in path: /tmp/dist-test-taskOATRPa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582035457-14253-0/minicluster-data/ts-0-root/wals/137fa0e68b214053a8455727fb68bda7/wal-000000038 (ops 185-189)
I20260812 06:19:53.003329 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: LogGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:53.003866 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7): 492 bytes on disk
I20260812 06:19:53.004333 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: UndoDeltaBlockGCOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.004932 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=3.181125
I20260812 06:19:53.030429 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.025s	user 0.005s	sys 0.019s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5742,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.031088 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:53.043226 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4725,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.044106 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:53.302742 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.258s	user 0.185s	sys 0.073s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":588,"lbm_read_time_us":18686,"lbm_reads_lt_1ms":775,"lbm_write_time_us":46035,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:19:53.304431 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=15.087375
I20260812 06:19:53.332525 14253 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.378s	user 1.975s	sys 0.174s
I20260812 06:19:53.359845 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.053s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":24883,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:53.360540 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7): perf score=2.188937
I20260812 06:19:53.370347 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: FlushDeltaMemStoresOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.370817 14687 maintenance_manager.cc:419] P f87f4982fe40473fb7723dede60d7d26: Scheduling MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7): perf score=1.000000
I20260812 06:19:53.392539 14253 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.059s	user 0.002s	sys 0.000s
I20260812 06:19:53.393275 14253 tablet_server.cc:179] TabletServer@127.13.235.65:0 shutting down...
I20260812 06:19:53.519759 14613 maintenance_manager.cc:643] P f87f4982fe40473fb7723dede60d7d26: MajorDeltaCompactionOp(137fa0e68b214053a8455727fb68bda7) complete. Timing: real 0.149s	user 0.084s	sys 0.065s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512287,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1042,"lbm_read_time_us":10078,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24852,"lbm_writes_lt_1ms":543,"mutex_wait_us":397,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.520460 14253 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:53.520704 14253 tablet_replica.cc:333] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26: stopping tablet replica
I20260812 06:19:53.520884 14253 raft_consensus.cc:2243] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.521060 14253 raft_consensus.cc:2272] T 137fa0e68b214053a8455727fb68bda7 P f87f4982fe40473fb7723dede60d7d26 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.526649 14253 tablet_server.cc:196] TabletServer@127.13.235.65:0 shutdown complete.
I20260812 06:19:53.575033 14253 master.cc:562] Master@127.13.235.126:39607 shutting down...
I20260812 06:19:53.579353 14253 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.579588 14253 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.579650 14253 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2feceb2af91242c0ac728cc603294b6c: stopping tablet replica
I20260812 06:19:53.592504 14253 master.cc:584] Master@127.13.235.126:39607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5949 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11644 ms total)

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