[==========] 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:20:21.514818 24212 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.165.62:39479
I20260812 06:20:21.515839 24212 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:20:21.516454 24212 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.523207 24223 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:20:21.523371 24212 server_base.cc:1061] running on GCE node
W20260812 06:20:21.523200 24221 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:20:21.523515 24219 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:20:21.524019 24212 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.524148 24212 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:20:21.524214 24212 hybrid_clock.cc:648] HybridClock initialized: now 1786515621524211 us; error 0 us; skew 500 ppm
I20260812 06:20:21.526054 24212 webserver.cc:533] Webserver started at http://127.23.165.62:46105/ using document root <none> and password file <none>
I20260812 06:20:21.526698 24212 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.526788 24212 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.527053 24212 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.528745 24212 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/master-0-root/instance:
uuid: "865291602e0a4ef493af1b52cd03ce7a"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-bt4h"
I20260812 06:20:21.532449 24212 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:21.534584 24228 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:20:21.535629 24212 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:21.535778 24212 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/master-0-root
uuid: "865291602e0a4ef493af1b52cd03ce7a"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-bt4h"
I20260812 06:20:21.535885 24212 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-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:20:21.548096 24212 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.548790 24212 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:20:21.548982 24212 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.557101 24285 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.165.62:39479 every 8 connection(s)
I20260812 06:20:21.557102 24212 rpc_server.cc:307] RPC server started. Bound to: 127.23.165.62:39479
I20260812 06:20:21.559536 24286 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:20:21.565050 24286 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: Bootstrap starting.
I20260812 06:20:21.567907 24286 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.568919 24286 log.cc:826] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:21.570818 24286 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: No bootstrap required, opened a new log
I20260812 06:20:21.573735 24286 raft_consensus.cc:359] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER }
I20260812 06:20:21.573905 24286 raft_consensus.cc:385] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.574036 24286 raft_consensus.cc:740] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 865291602e0a4ef493af1b52cd03ce7a, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.574723 24286 consensus_queue.cc:260] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [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: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER }
I20260812 06:20:21.574892 24286 raft_consensus.cc:399] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.574970 24286 raft_consensus.cc:493] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.575155 24286 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.575979 24286 raft_consensus.cc:515] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER }
I20260812 06:20:21.576427 24286 leader_election.cc:304] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [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: 865291602e0a4ef493af1b52cd03ce7a; no voters: 
I20260812 06:20:21.576771 24286 leader_election.cc:290] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.576920 24289 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.577168 24289 raft_consensus.cc:697] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 1 LEADER]: Becoming Leader. State: Replica: 865291602e0a4ef493af1b52cd03ce7a, State: Running, Role: LEADER
I20260812 06:20:21.577646 24289 consensus_queue.cc:237] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [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: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER }
I20260812 06:20:21.577766 24286 sys_catalog.cc:565] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:21.579737 24291 sys_catalog.cc:455] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 865291602e0a4ef493af1b52cd03ce7a. Latest consensus state: current_term: 1 leader_uuid: "865291602e0a4ef493af1b52cd03ce7a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER } }
I20260812 06:20:21.579849 24291 sys_catalog.cc:458] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.580196 24290 sys_catalog.cc:455] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "865291602e0a4ef493af1b52cd03ce7a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "865291602e0a4ef493af1b52cd03ce7a" member_type: VOTER } }
I20260812 06:20:21.580278 24290 sys_catalog.cc:458] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:21.580430 24212 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:21.580659 24303 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:21.584251 24303 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:21.589740 24303 catalog_manager.cc:1383] Generated new cluster ID: 12f9c97f5fb34780b1ecf8da31d94f36
I20260812 06:20:21.589869 24303 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:21.599663 24303 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:21.600490 24303 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:21.609035 24303 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: Generated new TSK 0
I20260812 06:20:21.609669 24303 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:21.613817 24212 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:21.616768 24310 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:20:21.616838 24311 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:20:21.616845 24313 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:20:21.617125 24212 server_base.cc:1061] running on GCE node
I20260812 06:20:21.617318 24212 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:21.617367 24212 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:20:21.617383 24212 hybrid_clock.cc:648] HybridClock initialized: now 1786515621617383 us; error 0 us; skew 500 ppm
I20260812 06:20:21.618373 24212 webserver.cc:533] Webserver started at http://127.23.165.1:34687/ using document root <none> and password file <none>
I20260812 06:20:21.618582 24212 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:21.618666 24212 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:21.618753 24212 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:21.619145 24212 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/instance:
uuid: "d11c9172a486493a95af0f1da781dcfb"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-bt4h"
I20260812 06:20:21.620661 24212 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:21.621687 24318 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:20:21.621937 24212 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:21.622012 24212 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root
uuid: "d11c9172a486493a95af0f1da781dcfb"
format_stamp: "Formatted at 2026-08-12 06:20:21 on dist-test-slave-bt4h"
I20260812 06:20:21.622107 24212 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-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:20:21.648586 24212 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:21.649109 24212 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:21.649677 24212 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:21.650575 24212 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:21.650637 24212 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.650715 24212 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:21.650753 24212 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:21.657573 24212 rpc_server.cc:307] RPC server started. Bound to: 127.23.165.1:36799
I20260812 06:20:21.657609 24394 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.165.1:36799 every 8 connection(s)
I20260812 06:20:21.672870 24395 heartbeater.cc:344] Connected to a master server at 127.23.165.62:39479
I20260812 06:20:21.673197 24395 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:21.673717 24395 heartbeater.cc:507] Master 127.23.165.62:39479 requested a full tablet report, sending...
I20260812 06:20:21.675417 24247 ts_manager.cc:194] Registered new tserver with Master: d11c9172a486493a95af0f1da781dcfb (127.23.165.1:36799)
I20260812 06:20:21.676223 24212 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017989801s
I20260812 06:20:21.677059 24247 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43928
I20260812 06:20:21.686646 24247 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43930:
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:20:21.701540 24353 tablet_service.cc:1511] Processing CreateTablet for tablet 855acbe9965b4f8f8ffe2b61be7d2675 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1bfed289a52744d49f5f451401771fb1]), partition=
I20260812 06:20:21.702104 24353 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 855acbe9965b4f8f8ffe2b61be7d2675. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:21.704419 24408 tablet_bootstrap.cc:492] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Bootstrap starting.
I20260812 06:20:21.705690 24408 tablet_bootstrap.cc:654] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:21.707041 24408 tablet_bootstrap.cc:492] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: No bootstrap required, opened a new log
I20260812 06:20:21.707154 24408 ts_tablet_manager.cc:1403] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:21.707695 24408 raft_consensus.cc:359] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d11c9172a486493a95af0f1da781dcfb" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 36799 } }
I20260812 06:20:21.707830 24408 raft_consensus.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:21.707888 24408 raft_consensus.cc:740] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d11c9172a486493a95af0f1da781dcfb, State: Initialized, Role: FOLLOWER
I20260812 06:20:21.708030 24408 consensus_queue.cc:260] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [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: "d11c9172a486493a95af0f1da781dcfb" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 36799 } }
I20260812 06:20:21.708148 24408 raft_consensus.cc:399] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:21.708196 24408 raft_consensus.cc:493] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:21.708240 24408 raft_consensus.cc:3060] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:21.709540 24408 raft_consensus.cc:515] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d11c9172a486493a95af0f1da781dcfb" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 36799 } }
I20260812 06:20:21.709702 24408 leader_election.cc:304] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [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: d11c9172a486493a95af0f1da781dcfb; no voters: 
I20260812 06:20:21.709940 24408 leader_election.cc:290] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:21.710103 24410 raft_consensus.cc:2804] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:21.710345 24408 ts_tablet_manager.cc:1434] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:21.710343 24410 raft_consensus.cc:697] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 1 LEADER]: Becoming Leader. State: Replica: d11c9172a486493a95af0f1da781dcfb, State: Running, Role: LEADER
I20260812 06:20:21.710635 24410 consensus_queue.cc:237] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [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: "d11c9172a486493a95af0f1da781dcfb" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 36799 } }
I20260812 06:20:21.710770 24395 heartbeater.cc:499] Master 127.23.165.62:39479 was elected leader, sending a full tablet report...
I20260812 06:20:21.713968 24247 catalog_manager.cc:5719] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb reported cstate change: term changed from 0 to 1, leader changed from <none> to d11c9172a486493a95af0f1da781dcfb (127.23.165.1). New cstate: current_term: 1 leader_uuid: "d11c9172a486493a95af0f1da781dcfb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d11c9172a486493a95af0f1da781dcfb" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 36799 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:21.784833 24212 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.022s	sys 0.008s
I20260812 06:20:21.908677 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=15.086190
I20260812 06:20:22.088541 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.180s	user 0.142s	sys 0.032s Metrics: {"bytes_written":13169000,"cfile_init":1,"compiler_manager_pool.queue_time_us":187,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":982,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43774,"lbm_writes_lt_1ms":688,"mutex_wait_us":1863,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":145024,"thread_start_us":126,"threads_started":1,"update_count":1605}
I20260812 06:20:22.090255 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675): free 20743880 bytes of WAL
I20260812 06:20:22.090626 24324 log_reader.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675: removed 2 log segments from log reader
I20260812 06:20:22.090735 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000001 (ops 1-6)
I20260812 06:20:22.090868 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000002 (ops 7-11)
I20260812 06:20:22.096063 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:22.096444 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.115702 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.019s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3339,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:20:22.116227 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.130107 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5424,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.130594 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:22.300107 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.169s	user 0.100s	sys 0.069s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364539,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":574,"lbm_read_time_us":13921,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31577,"lbm_writes_lt_1ms":533,"mutex_wait_us":31,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":332,"threads_started":5,"update_count":2450}
I20260812 06:20:22.300729 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:22.343595 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.043s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15183,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.344156 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675): 12719216 bytes on disk
I20260812 06:20:22.344699 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.345134 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.356820 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.357522 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:22.491186 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.133s	user 0.099s	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":984,"lbm_read_time_us":10188,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26453,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:22.491815 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:22.538853 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.047s	user 0.028s	sys 0.009s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17694,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.539433 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.555706 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.556330 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:22.708976 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.152s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":12228,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30150,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2000}
I20260812 06:20:22.709683 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:22.767575 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.058s	user 0.020s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18255,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.768186 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.779457 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.779961 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:22.937397 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.157s	user 0.104s	sys 0.050s 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":187,"lbm_read_time_us":12051,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26227,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.938508 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:22.980381 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.042s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15956,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:22.980832 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:22.993659 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.994388 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:23.129258 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.135s	user 0.102s	sys 0.032s 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":189,"lbm_read_time_us":9686,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25833,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:20:23.129909 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:23.172358 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.042s	user 0.039s	sys 0.000s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17353,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.172876 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:23.185149 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.012s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.185817 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:23.315582 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.130s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":8542,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27565,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:20:23.316259 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:23.368572 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.052s	user 0.011s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15409,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.369164 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:23.380211 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4294,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.380654 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:23.425771 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.045s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1333,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1608,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:23.426733 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675): free 112692376 bytes of WAL
I20260812 06:20:23.426999 24324 log_reader.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675: removed 11 log segments from log reader
I20260812 06:20:23.427060 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000003 (ops 12-16)
I20260812 06:20:23.427099 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000004 (ops 17-21)
I20260812 06:20:23.427134 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000005 (ops 22-26)
I20260812 06:20:23.427167 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000006 (ops 27-31)
I20260812 06:20:23.427189 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000007 (ops 32-36)
I20260812 06:20:23.427210 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000008 (ops 37-41)
I20260812 06:20:23.427239 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000009 (ops 42-46)
I20260812 06:20:23.427276 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000010 (ops 47-51)
I20260812 06:20:23.427309 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000011 (ops 52-56)
I20260812 06:20:23.427335 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000012 (ops 57-61)
I20260812 06:20:23.427356 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000013 (ops 62-66)
I20260812 06:20:23.458509 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:23.459143 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675): 447 bytes on disk
I20260812 06:20:23.459790 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.460400 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=3.181125
I20260812 06:20:23.486941 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.026s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5279,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:23.487450 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:23.497843 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3942,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.498311 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:23.707544 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.209s	user 0.134s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":8346,"lbm_read_time_us":13680,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34558,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:20:23.708271 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:23.755079 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.047s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20738,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.755683 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:23.772517 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.773042 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:23.960322 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.187s	user 0.121s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":15519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31340,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:20:23.962886 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:24.029706 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.067s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23326,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.030213 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:24.042119 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.042788 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:24.219172 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.176s	user 0.136s	sys 0.037s 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":165,"lbm_read_time_us":11964,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29935,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:24.219756 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:24.287252 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.067s	user 0.040s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23477,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.287859 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:24.298981 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.299434 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:24.505748 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.206s	user 0.128s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":13563,"lbm_reads_lt_1ms":572,"lbm_write_time_us":38583,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:20:24.506290 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=11.118625
I20260812 06:20:24.548403 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.042s	user 0.011s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18148,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:24.548951 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:24.589816 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.041s	user 0.008s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5088,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.590576 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:24.607249 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.607870 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:24.795161 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.187s	user 0.111s	sys 0.076s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":941,"lbm_read_time_us":15390,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31114,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:20:24.796147 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:24.834548 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.037s	user 0.026s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.835325 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:24.851820 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.852394 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:24.986389 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.134s	user 0.080s	sys 0.053s 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":1348,"lbm_read_time_us":10149,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24738,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:24.987000 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:25.034092 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.047s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.034729 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.050673 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.051239 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:25.090291 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.039s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1370,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1940,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:25.091078 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675): free 120553380 bytes of WAL
I20260812 06:20:25.091339 24324 log_reader.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675: removed 12 log segments from log reader
I20260812 06:20:25.091419 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000014 (ops 67-71)
I20260812 06:20:25.091480 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000015 (ops 72-76)
I20260812 06:20:25.091521 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000016 (ops 77-80)
I20260812 06:20:25.091563 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000017 (ops 81-85)
I20260812 06:20:25.091602 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000018 (ops 86-90)
I20260812 06:20:25.091643 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000019 (ops 91-94)
I20260812 06:20:25.091686 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000020 (ops 95-99)
I20260812 06:20:25.091727 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000021 (ops 100-104)
I20260812 06:20:25.091766 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000022 (ops 105-109)
I20260812 06:20:25.091806 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000023 (ops 110-114)
I20260812 06:20:25.091846 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000024 (ops 115-119)
I20260812 06:20:25.091886 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000025 (ops 120-124)
I20260812 06:20:25.123528 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:25.124020 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=3.181125
I20260812 06:20:25.137518 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5103,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.138043 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675): free 11564877 bytes of WAL
I20260812 06:20:25.138298 24324 log_reader.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675: removed 1 log segments from log reader
I20260812 06:20:25.138358 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000026 (ops 125-128)
I20260812 06:20:25.142899 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:20:25.143244 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.159353 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5720,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.160015 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675): 473 bytes on disk
I20260812 06:20:25.160601 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":172,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.161294 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:25.343300 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.182s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":265,"lbm_read_time_us":14021,"lbm_reads_lt_1ms":666,"lbm_write_time_us":40522,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:25.343964 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:25.390602 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.046s	user 0.040s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18867,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.391256 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.402274 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.402794 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:25.554170 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.151s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":11295,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29225,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:25.554833 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=10.126437
I20260812 06:20:25.597975 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.043s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18521,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.599170 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.625450 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.625957 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.636981 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.637555 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:25.806097 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.168s	user 0.139s	sys 0.021s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":639,"lbm_read_time_us":11275,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32496,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:20:25.806730 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:25.860793 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.054s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19016,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.861279 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:25.873253 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.874001 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.030823 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.157s	user 0.096s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3038,"lbm_read_time_us":11511,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29942,"lbm_writes_lt_1ms":543,"mutex_wait_us":2588,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:20:26.032464 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=13.103000
I20260812 06:20:26.088483 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.056s	user 0.033s	sys 0.012s Metrics: {"bytes_written":14645857,"delete_count":0,"lbm_write_time_us":22795,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":359,"reinsert_count":0,"update_count":1785}
I20260812 06:20:26.088954 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=4.173312
I20260812 06:20:26.106616 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":5866708,"delete_count":0,"lbm_write_time_us":7222,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:20:26.107205 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.271333 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.164s	user 0.099s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":380,"lbm_read_time_us":12567,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30401,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:26.272054 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:26.332381 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.060s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24510,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.332934 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:26.349476 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.350131 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.537035 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.187s	user 0.138s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":13711,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31941,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:26.537952 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:26.602165 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.064s	user 0.041s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.602836 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:26.613790 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.614279 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.659111 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushMRSOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.045s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1385,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1631,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:26.659834 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675): free 121006700 bytes of WAL
I20260812 06:20:26.660074 24324 log_reader.cc:385] T 855acbe9965b4f8f8ffe2b61be7d2675: removed 12 log segments from log reader
I20260812 06:20:26.660120 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000027 (ops 129-133)
I20260812 06:20:26.660151 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000028 (ops 134-138)
I20260812 06:20:26.660221 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000029 (ops 139-142)
I20260812 06:20:26.660265 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000030 (ops 143-147)
I20260812 06:20:26.660307 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000031 (ops 148-152)
I20260812 06:20:26.660365 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000032 (ops 153-157)
I20260812 06:20:26.660404 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000033 (ops 158-162)
I20260812 06:20:26.660444 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000034 (ops 163-167)
I20260812 06:20:26.660485 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000035 (ops 168-172)
I20260812 06:20:26.660523 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000036 (ops 173-177)
I20260812 06:20:26.660562 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000037 (ops 178-182)
I20260812 06:20:26.660601 24324 log.cc:1079] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/855acbe9965b4f8f8ffe2b61be7d2675/wal-000000038 (ops 183-187)
I20260812 06:20:26.688512 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: LogGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:26.688941 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675): 492 bytes on disk
I20260812 06:20:26.689373 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: UndoDeltaBlockGCOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:26.689917 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=3.181125
I20260812 06:20:26.703452 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:26.704003 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=2.188937
I20260812 06:20:26.713632 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:26.714154 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.910917 24212 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.126s	user 1.885s	sys 0.120s
I20260812 06:20:26.927189 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.213s	user 0.132s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17460,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37965,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3500}
I20260812 06:20:26.927680 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=14.095187
I20260812 06:20:26.960382 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: FlushDeltaMemStoresOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.032s	user 0.024s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":15654,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.960819 24396 maintenance_manager.cc:419] P d11c9172a486493a95af0f1da781dcfb: Scheduling MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675): perf score=1.000000
I20260812 06:20:26.990677 24212 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.006s	sys 0.000s
I20260812 06:20:26.991454 24212 tablet_server.cc:179] TabletServer@127.23.165.1:0 shutting down...
I20260812 06:20:27.082288 24324 maintenance_manager.cc:643] P d11c9172a486493a95af0f1da781dcfb: MajorDeltaCompactionOp(855acbe9965b4f8f8ffe2b61be7d2675) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":461,"lbm_read_time_us":8498,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26199,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:20:27.083056 24212 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:27.083531 24212 tablet_replica.cc:333] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb: stopping tablet replica
I20260812 06:20:27.083811 24212 raft_consensus.cc:2243] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.084054 24212 raft_consensus.cc:2272] T 855acbe9965b4f8f8ffe2b61be7d2675 P d11c9172a486493a95af0f1da781dcfb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.099944 24212 tablet_server.cc:196] TabletServer@127.23.165.1:0 shutdown complete.
I20260812 06:20:27.122310 24212 master.cc:562] Master@127.23.165.62:39479 shutting down...
I20260812 06:20:27.126061 24212 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:27.126286 24212 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:27.126394 24212 tablet_replica.cc:333] T 00000000000000000000000000000000 P 865291602e0a4ef493af1b52cd03ce7a: stopping tablet replica
I20260812 06:20:27.138973 24212 master.cc:584] Master@127.23.165.62:39479 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5725 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:27.254859 24212 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.165.62:41653
I20260812 06:20:27.255303 24212 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:27.257546 24429 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:20:27.257527 24432 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:20:27.257766 24212 server_base.cc:1061] running on GCE node
W20260812 06:20:27.257640 24430 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:20:27.258011 24212 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:27.258059 24212 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:20:27.258075 24212 hybrid_clock.cc:648] HybridClock initialized: now 1786515627258075 us; error 0 us; skew 500 ppm
I20260812 06:20:27.259006 24212 webserver.cc:533] Webserver started at http://127.23.165.62:34459/ using document root <none> and password file <none>
I20260812 06:20:27.259152 24212 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:27.259202 24212 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:27.259268 24212 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:27.259639 24212 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/master-0-root/instance:
uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-bt4h"
I20260812 06:20:27.261148 24212 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:27.262192 24437 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:20:27.262564 24212 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:27.262650 24212 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/master-0-root
uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-bt4h"
I20260812 06:20:27.262735 24212 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-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:20:27.267759 24212 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:27.268081 24212 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:27.272090 24212 rpc_server.cc:307] RPC server started. Bound to: 127.23.165.62:41653
I20260812 06:20:27.273545 24499 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:20:27.274673 24498 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.165.62:41653 every 8 connection(s)
I20260812 06:20:27.278885 24499 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7: Bootstrap starting.
I20260812 06:20:27.279690 24499 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:27.280894 24499 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7: No bootstrap required, opened a new log
I20260812 06:20:27.281316 24499 raft_consensus.cc:359] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER }
I20260812 06:20:27.281406 24499 raft_consensus.cc:385] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:27.281430 24499 raft_consensus.cc:740] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a7093f7ebde142c2bfffdc5f2d1f4cc7, State: Initialized, Role: FOLLOWER
I20260812 06:20:27.281596 24499 consensus_queue.cc:260] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [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: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER }
I20260812 06:20:27.281687 24499 raft_consensus.cc:399] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:27.281716 24499 raft_consensus.cc:493] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:27.281755 24499 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:27.282437 24499 raft_consensus.cc:515] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER }
I20260812 06:20:27.282616 24499 leader_election.cc:304] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [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: a7093f7ebde142c2bfffdc5f2d1f4cc7; no voters: 
I20260812 06:20:27.282817 24499 leader_election.cc:290] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:27.282910 24503 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:27.283090 24503 raft_consensus.cc:697] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 1 LEADER]: Becoming Leader. State: Replica: a7093f7ebde142c2bfffdc5f2d1f4cc7, State: Running, Role: LEADER
I20260812 06:20:27.283223 24503 consensus_queue.cc:237] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [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: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER }
I20260812 06:20:27.283346 24499 sys_catalog.cc:565] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:27.283706 24506 sys_catalog.cc:455] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER } }
I20260812 06:20:27.283721 24503 sys_catalog.cc:455] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a7093f7ebde142c2bfffdc5f2d1f4cc7. Latest consensus state: current_term: 1 leader_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7093f7ebde142c2bfffdc5f2d1f4cc7" member_type: VOTER } }
I20260812 06:20:27.283876 24506 sys_catalog.cc:458] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:27.283967 24503 sys_catalog.cc:458] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:27.284562 24510 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:27.285458 24510 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:27.285665 24212 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:27.287374 24510 catalog_manager.cc:1383] Generated new cluster ID: 9471a61496ba4073848bb34ac259e680
I20260812 06:20:27.287436 24510 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:27.297503 24510 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:27.298115 24510 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:27.306972 24510 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7: Generated new TSK 0
I20260812 06:20:27.307197 24510 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:27.318368 24212 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:27.320936 24525 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:20:27.320938 24527 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:20:27.321076 24524 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:20:27.321346 24212 server_base.cc:1061] running on GCE node
I20260812 06:20:27.321591 24212 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:27.321635 24212 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:20:27.321655 24212 hybrid_clock.cc:648] HybridClock initialized: now 1786515627321654 us; error 0 us; skew 500 ppm
I20260812 06:20:27.322680 24212 webserver.cc:533] Webserver started at http://127.23.165.1:42353/ using document root <none> and password file <none>
I20260812 06:20:27.322876 24212 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:27.322947 24212 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:27.323041 24212 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:27.323487 24212 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/instance:
uuid: "0562730805bc4c60b1aa3e2d54f874e8"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-bt4h"
I20260812 06:20:27.325045 24212 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:27.326017 24532 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:20:27.326248 24212 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:27.326344 24212 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root
uuid: "0562730805bc4c60b1aa3e2d54f874e8"
format_stamp: "Formatted at 2026-08-12 06:20:27 on dist-test-slave-bt4h"
I20260812 06:20:27.326444 24212 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-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:20:27.333317 24212 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:27.333717 24212 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:27.334060 24212 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:27.334604 24212 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:27.334661 24212 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:27.334720 24212 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:27.334769 24212 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:27.339028 24212 rpc_server.cc:307] RPC server started. Bound to: 127.23.165.1:38293
I20260812 06:20:27.340999 24600 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.165.1:38293 every 8 connection(s)
I20260812 06:20:27.349292 24601 heartbeater.cc:344] Connected to a master server at 127.23.165.62:41653
I20260812 06:20:27.349466 24601 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:27.349759 24601 heartbeater.cc:507] Master 127.23.165.62:41653 requested a full tablet report, sending...
I20260812 06:20:27.350433 24456 ts_manager.cc:194] Registered new tserver with Master: 0562730805bc4c60b1aa3e2d54f874e8 (127.23.165.1:38293)
I20260812 06:20:27.351207 24212 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011102234s
I20260812 06:20:27.351294 24456 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33722
I20260812 06:20:27.358771 24456 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33724:
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:20:27.367811 24561 tablet_service.cc:1511] Processing CreateTablet for tablet 859ee92772894499a6ce225c8f5b7801 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5d64e23cb59a4f3ea7350c811902ea57]), partition=
I20260812 06:20:27.368116 24561 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 859ee92772894499a6ce225c8f5b7801. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:27.370074 24613 tablet_bootstrap.cc:492] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Bootstrap starting.
I20260812 06:20:27.370970 24613 tablet_bootstrap.cc:654] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:27.372002 24613 tablet_bootstrap.cc:492] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: No bootstrap required, opened a new log
I20260812 06:20:27.372078 24613 ts_tablet_manager.cc:1403] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:27.372416 24613 raft_consensus.cc:359] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0562730805bc4c60b1aa3e2d54f874e8" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 38293 } }
I20260812 06:20:27.372503 24613 raft_consensus.cc:385] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:27.372529 24613 raft_consensus.cc:740] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0562730805bc4c60b1aa3e2d54f874e8, State: Initialized, Role: FOLLOWER
I20260812 06:20:27.372625 24613 consensus_queue.cc:260] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [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: "0562730805bc4c60b1aa3e2d54f874e8" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 38293 } }
I20260812 06:20:27.372758 24613 raft_consensus.cc:399] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:27.372807 24613 raft_consensus.cc:493] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:27.372856 24613 raft_consensus.cc:3060] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:27.373646 24613 raft_consensus.cc:515] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0562730805bc4c60b1aa3e2d54f874e8" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 38293 } }
I20260812 06:20:27.373773 24613 leader_election.cc:304] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [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: 0562730805bc4c60b1aa3e2d54f874e8; no voters: 
I20260812 06:20:27.373934 24613 leader_election.cc:290] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:27.374063 24615 raft_consensus.cc:2804] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:27.374300 24613 ts_tablet_manager.cc:1434] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:27.374387 24601 heartbeater.cc:499] Master 127.23.165.62:41653 was elected leader, sending a full tablet report...
I20260812 06:20:27.374338 24615 raft_consensus.cc:697] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 1 LEADER]: Becoming Leader. State: Replica: 0562730805bc4c60b1aa3e2d54f874e8, State: Running, Role: LEADER
I20260812 06:20:27.374562 24615 consensus_queue.cc:237] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [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: "0562730805bc4c60b1aa3e2d54f874e8" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 38293 } }
I20260812 06:20:27.375861 24456 catalog_manager.cc:5719] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0562730805bc4c60b1aa3e2d54f874e8 (127.23.165.1). New cstate: current_term: 1 leader_uuid: "0562730805bc4c60b1aa3e2d54f874e8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0562730805bc4c60b1aa3e2d54f874e8" member_type: VOTER last_known_addr { host: "127.23.165.1" port: 38293 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:27.438578 24212 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.004s
I20260812 06:20:27.591692 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushMRSOp(859ee92772894499a6ce225c8f5b7801): perf score=19.054940
I20260812 06:20:27.757149 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushMRSOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.165s	user 0.111s	sys 0.052s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":719,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43233,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:27.757937 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling LogGCOp(859ee92772894499a6ce225c8f5b7801): free 20743880 bytes of WAL
I20260812 06:20:27.758265 24537 log_reader.cc:385] T 859ee92772894499a6ce225c8f5b7801: removed 2 log segments from log reader
I20260812 06:20:27.758355 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000001 (ops 1-6)
I20260812 06:20:27.758407 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000002 (ops 7-11)
I20260812 06:20:27.765149 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: LogGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:27.765655 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801): 16411392 bytes on disk
I20260812 06:20:27.766320 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:20:27.766819 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:27.783839 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.784565 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:27.951622 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.167s	user 0.119s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":11241,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24778,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":325,"threads_started":5,"update_count":2000}
I20260812 06:20:27.952291 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:28.007197 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.055s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.007711 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:28.031533 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.024s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.032094 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:28.259637 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.227s	user 0.147s	sys 0.080s 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":486,"lbm_read_time_us":16350,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39000,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:20:28.260277 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:28.316015 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.056s	user 0.019s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24521,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.316594 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:28.328835 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4617,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.329479 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:28.511727 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.182s	user 0.107s	sys 0.062s 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":812,"lbm_read_time_us":13127,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28153,"lbm_writes_lt_1ms":543,"mutex_wait_us":403,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:20:28.512421 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:28.565891 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.053s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20112,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:20:28.566378 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:28.581152 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.581670 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:28.773216 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.191s	user 0.139s	sys 0.040s 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":1233,"lbm_read_time_us":13120,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36481,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2500}
I20260812 06:20:28.773912 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:28.828763 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.055s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23094,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:28.829252 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:28.841950 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.013s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.842643 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:28.994318 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.151s	user 0.124s	sys 0.026s 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":862,"lbm_read_time_us":11177,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29954,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:28.995052 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=11.118625
I20260812 06:20:29.032372 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15975,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:29.032981 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.058400 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5255,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.058995 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.074041 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.074733 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushMRSOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:29.109092 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushMRSOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1713,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1815,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:29.109879 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling LogGCOp(859ee92772894499a6ce225c8f5b7801): free 115943176 bytes of WAL
I20260812 06:20:29.110128 24537 log_reader.cc:385] T 859ee92772894499a6ce225c8f5b7801: removed 11 log segments from log reader
I20260812 06:20:29.110201 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000003 (ops 12-16)
I20260812 06:20:29.110299 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000004 (ops 17-21)
I20260812 06:20:29.110360 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000005 (ops 22-26)
I20260812 06:20:29.110401 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000006 (ops 27-31)
I20260812 06:20:29.110438 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000007 (ops 32-36)
I20260812 06:20:29.110476 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000008 (ops 37-41)
I20260812 06:20:29.110512 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000009 (ops 42-46)
I20260812 06:20:29.110580 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000010 (ops 47-51)
I20260812 06:20:29.110618 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000011 (ops 52-56)
I20260812 06:20:29.110656 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000012 (ops 57-61)
I20260812 06:20:29.110692 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000013 (ops 62-66)
I20260812 06:20:29.139529 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: LogGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:29.140017 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=3.181125
I20260812 06:20:29.159221 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7326,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:29.159734 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.171661 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.172257 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801): 463 bytes on disk
I20260812 06:20:29.172712 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:20:29.173235 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:29.378558 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.205s	user 0.146s	sys 0.057s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979846,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1408,"lbm_read_time_us":14314,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42905,"lbm_writes_lt_1ms":743,"mutex_wait_us":286,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:20:29.379345 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=15.087375
I20260812 06:20:29.442991 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.063s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23899,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:20:29.443498 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.454591 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.455050 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.464671 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3553,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:29.465106 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:29.643949 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.179s	user 0.130s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":324,"lbm_read_time_us":13121,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36155,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":3000}
I20260812 06:20:29.644625 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:29.697190 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.052s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.697678 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:29.709734 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.710350 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:29.889958 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.179s	user 0.134s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":257,"lbm_read_time_us":11042,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31768,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:29.890674 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:29.950922 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.060s	user 0.047s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26510,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.951393 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:30.108511 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.157s	user 0.111s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":824,"lbm_read_time_us":10622,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25272,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:20:30.109130 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:30.169147 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.060s	user 0.035s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27759,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.169775 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:30.181387 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.182112 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:30.378504 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.196s	user 0.139s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":465,"lbm_read_time_us":11795,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29591,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:20:30.379151 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:30.436846 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.058s	user 0.023s	sys 0.026s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":23136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.437353 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:30.449225 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4467,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.449729 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:30.617902 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.168s	user 0.110s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":10841,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31317,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:30.618873 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=11.118625
I20260812 06:20:30.655356 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.036s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15345,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:30.656052 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:30.672438 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:30.672927 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushMRSOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:30.728412 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushMRSOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.055s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":308,"dirs.run_wall_time_us":1376,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2714,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:30.729084 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling LogGCOp(859ee92772894499a6ce225c8f5b7801): free 133024372 bytes of WAL
I20260812 06:20:30.729317 24537 log_reader.cc:385] T 859ee92772894499a6ce225c8f5b7801: removed 13 log segments from log reader
I20260812 06:20:30.729378 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000014 (ops 67-71)
I20260812 06:20:30.729434 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000015 (ops 72-76)
I20260812 06:20:30.729490 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000016 (ops 77-81)
I20260812 06:20:30.729530 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000017 (ops 82-86)
I20260812 06:20:30.729564 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000018 (ops 87-91)
I20260812 06:20:30.729598 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000019 (ops 92-96)
I20260812 06:20:30.729633 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000020 (ops 97-101)
I20260812 06:20:30.729672 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000021 (ops 102-106)
I20260812 06:20:30.729708 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000022 (ops 107-111)
I20260812 06:20:30.729744 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000023 (ops 112-116)
I20260812 06:20:30.729780 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000024 (ops 117-121)
I20260812 06:20:30.729822 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000025 (ops 122-126)
I20260812 06:20:30.729858 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000026 (ops 127-130)
I20260812 06:20:30.760282 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: LogGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:20:30.760785 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801): 491 bytes on disk
I20260812 06:20:30.761325 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801) 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:20:30.761830 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=7.149875
I20260812 06:20:30.799206 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.037s	user 0.020s	sys 0.016s Metrics: {"bytes_written":9353756,"delete_count":0,"lbm_write_time_us":10318,"lbm_writes_lt_1ms":231,"mutex_wait_us":139,"reinsert_count":0,"update_count":1140}
I20260812 06:20:30.799898 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=1.196750
I20260812 06:20:30.813608 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.014s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3113,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:20:30.814127 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:31.063947 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.250s	user 0.184s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979716,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":648,"lbm_read_time_us":15799,"lbm_reads_lt_1ms":766,"lbm_write_time_us":40401,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":25856,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:20:31.064798 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=18.063937
I20260812 06:20:31.124189 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.059s	user 0.041s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26398,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:31.124779 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:31.149353 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.149855 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:31.160983 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.161666 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:31.403391 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.242s	user 0.170s	sys 0.071s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979635,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1355,"lbm_read_time_us":18876,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43078,"lbm_writes_lt_1ms":743,"mutex_wait_us":313,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":35584,"update_count":3500}
I20260812 06:20:31.403935 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=18.063937
I20260812 06:20:31.471794 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.068s	user 0.045s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31579,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:31.472349 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:31.485589 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.486066 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:31.665961 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.180s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2331,"lbm_read_time_us":12347,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38571,"lbm_writes_lt_1ms":643,"mutex_wait_us":642,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:20:31.669539 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:31.720435 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.051s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22323,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.721037 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:31.739326 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.740023 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:31.914909 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.175s	user 0.127s	sys 0.039s 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":232,"lbm_read_time_us":12498,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31593,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":72192,"update_count":2500}
I20260812 06:20:31.915870 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:31.963995 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21638,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.964514 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:32.117162 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.152s	user 0.080s	sys 0.068s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":143,"lbm_read_time_us":11711,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24512,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:32.117952 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=11.118625
I20260812 06:20:32.157114 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.039s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16669,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:32.157781 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:32.184950 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.027s	user 0.000s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5380,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.185470 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:32.196362 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.196903 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushMRSOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:32.239595 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushMRSOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.042s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1264,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1737,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:32.240438 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling LogGCOp(859ee92772894499a6ce225c8f5b7801): free 121006648 bytes of WAL
I20260812 06:20:32.240710 24537 log_reader.cc:385] T 859ee92772894499a6ce225c8f5b7801: removed 12 log segments from log reader
I20260812 06:20:32.240759 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000027 (ops 131-135)
I20260812 06:20:32.240789 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000028 (ops 136-140)
I20260812 06:20:32.240805 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000029 (ops 141-145)
I20260812 06:20:32.240883 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000030 (ops 146-150)
I20260812 06:20:32.240931 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000031 (ops 151-155)
I20260812 06:20:32.240978 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000032 (ops 156-160)
I20260812 06:20:32.241034 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000033 (ops 161-165)
I20260812 06:20:32.241075 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000034 (ops 166-170)
I20260812 06:20:32.241117 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000035 (ops 171-174)
I20260812 06:20:32.241156 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000036 (ops 175-179)
I20260812 06:20:32.241195 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000037 (ops 180-184)
I20260812 06:20:32.241235 24537 log.cc:1079] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: Deleting log segment in path: /tmp/dist-test-task_oyI9u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515621504150-24212-0/minicluster-data/ts-0-root/wals/859ee92772894499a6ce225c8f5b7801/wal-000000038 (ops 185-189)
I20260812 06:20:32.270732 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: LogGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:32.271162 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801): 462 bytes on disk
I20260812 06:20:32.271621 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: UndoDeltaBlockGCOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:32.272189 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:32.296693 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.024s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.297273 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=2.188937
I20260812 06:20:32.308424 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4395,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.309073 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:32.500222 24212 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.062s	user 1.861s	sys 0.176s
I20260812 06:20:32.545192 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.236s	user 0.167s	sys 0.067s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":18057,"lbm_reads_lt_1ms":771,"lbm_write_time_us":38493,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":3500}
I20260812 06:20:32.545732 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801): perf score=14.095187
I20260812 06:20:32.579469 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: FlushDeltaMemStoresOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.034s	user 0.020s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.580005 24602 maintenance_manager.cc:419] P 0562730805bc4c60b1aa3e2d54f874e8: Scheduling MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801): perf score=1.000000
I20260812 06:20:32.613274 24212 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.113s	user 0.001s	sys 0.000s
I20260812 06:20:32.613816 24212 tablet_server.cc:179] TabletServer@127.23.165.1:0 shutting down...
I20260812 06:20:32.714016 24537 maintenance_manager.cc:643] P 0562730805bc4c60b1aa3e2d54f874e8: MajorDeltaCompactionOp(859ee92772894499a6ce225c8f5b7801) complete. Timing: real 0.134s	user 0.099s	sys 0.034s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":973,"lbm_read_time_us":12500,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25996,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":141,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:32.714846 24212 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:32.715092 24212 tablet_replica.cc:333] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8: stopping tablet replica
I20260812 06:20:32.715286 24212 raft_consensus.cc:2243] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:32.715462 24212 raft_consensus.cc:2272] T 859ee92772894499a6ce225c8f5b7801 P 0562730805bc4c60b1aa3e2d54f874e8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:32.719254 24212 tablet_server.cc:196] TabletServer@127.23.165.1:0 shutdown complete.
I20260812 06:20:32.753433 24212 master.cc:562] Master@127.23.165.62:41653 shutting down...
I20260812 06:20:32.756855 24212 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:32.757043 24212 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:32.757095 24212 tablet_replica.cc:333] T 00000000000000000000000000000000 P a7093f7ebde142c2bfffdc5f2d1f4cc7: stopping tablet replica
I20260812 06:20:32.769599 24212 master.cc:584] Master@127.23.165.62:41653 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5627 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11353 ms total)

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