[==========] 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:18:43.680101  1076 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.13.62:35563
I20260812 06:18:43.681172  1076 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:18:43.681800  1076 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.688069  1090 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.688074  1082 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:43.688230  1076 server_base.cc:1061] running on GCE node
W20260812 06:18:43.688361  1087 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:18:43.688894  1076 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.689016  1076 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:43.689064  1076 hybrid_clock.cc:648] HybridClock initialized: now 1786515523689060 us; error 0 us; skew 500 ppm
I20260812 06:18:43.690853  1076 webserver.cc:533] Webserver started at http://127.1.13.62:41441/ using document root <none> and password file <none>
I20260812 06:18:43.691417  1076 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.691494  1076 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.691748  1076 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.693434  1076 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/master-0-root/instance:
uuid: "dd1fe9eedd324292b5c975301dbb216d"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-44d2"
I20260812 06:18:43.696844  1076 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:43.698796  1097 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.699824  1076 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:43.699968  1076 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/master-0-root
uuid: "dd1fe9eedd324292b5c975301dbb216d"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-44d2"
I20260812 06:18:43.700076  1076 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:43.726351  1076 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.727048  1076 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:18:43.727236  1076 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.735399  1076 rpc_server.cc:307] RPC server started. Bound to: 127.1.13.62:35563
I20260812 06:18:43.735406  1183 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.13.62:35563 every 8 connection(s)
I20260812 06:18:43.737774  1190 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.743083  1190 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: Bootstrap starting.
I20260812 06:18:43.745543  1190 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.746439  1190 log.cc:826] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:43.748222  1190 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: No bootstrap required, opened a new log
I20260812 06:18:43.751072  1190 raft_consensus.cc:359] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER }
I20260812 06:18:43.751252  1190 raft_consensus.cc:385] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.751327  1190 raft_consensus.cc:740] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dd1fe9eedd324292b5c975301dbb216d, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.751933  1190 consensus_queue.cc:260] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [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: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER }
I20260812 06:18:43.752071  1190 raft_consensus.cc:399] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.752173  1190 raft_consensus.cc:493] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.752336  1190 raft_consensus.cc:3060] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.753161  1190 raft_consensus.cc:515] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER }
I20260812 06:18:43.753600  1190 leader_election.cc:304] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [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: dd1fe9eedd324292b5c975301dbb216d; no voters: 
I20260812 06:18:43.753911  1190 leader_election.cc:290] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.754264  1194 raft_consensus.cc:2804] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.754494  1194 raft_consensus.cc:697] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 1 LEADER]: Becoming Leader. State: Replica: dd1fe9eedd324292b5c975301dbb216d, State: Running, Role: LEADER
I20260812 06:18:43.754890  1190 sys_catalog.cc:565] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.754864  1194 consensus_queue.cc:237] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [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: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER }
I20260812 06:18:43.756776  1195 sys_catalog.cc:455] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "dd1fe9eedd324292b5c975301dbb216d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER } }
I20260812 06:18:43.756829  1196 sys_catalog.cc:455] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [sys.catalog]: SysCatalogTable state changed. Reason: New leader dd1fe9eedd324292b5c975301dbb216d. Latest consensus state: current_term: 1 leader_uuid: "dd1fe9eedd324292b5c975301dbb216d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dd1fe9eedd324292b5c975301dbb216d" member_type: VOTER } }
I20260812 06:18:43.756909  1195 sys_catalog.cc:458] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.756913  1196 sys_catalog.cc:458] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.757285  1212 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.757318  1076 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.759539  1212 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.764247  1212 catalog_manager.cc:1383] Generated new cluster ID: dbe788daa3564bbeb55f869f2268b49a
I20260812 06:18:43.764313  1212 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.778918  1212 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.780089  1212 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.788975  1212 catalog_manager.cc:6092] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: Generated new TSK 0
I20260812 06:18:43.789755  1212 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.822270  1076 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.825249  1220 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.825430  1222 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:43.825256  1225 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:43.825670  1076 server_base.cc:1061] running on GCE node
I20260812 06:18:43.825855  1076 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.825917  1076 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:43.825950  1076 hybrid_clock.cc:648] HybridClock initialized: now 1786515523825950 us; error 0 us; skew 500 ppm
I20260812 06:18:43.827067  1076 webserver.cc:533] Webserver started at http://127.1.13.1:44901/ using document root <none> and password file <none>
I20260812 06:18:43.827275  1076 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.827346  1076 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.827437  1076 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.827853  1076 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/instance:
uuid: "935d7877fdab43788aaea6895ea21eac"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-44d2"
I20260812 06:18:43.829545  1076 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:43.830586  1234 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.830849  1076 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:43.830926  1076 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root
uuid: "935d7877fdab43788aaea6895ea21eac"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-44d2"
I20260812 06:18:43.831025  1076 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:43.838835  1076 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.839284  1076 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.839795  1076 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.840737  1076 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.840792  1076 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.840865  1076 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.840903  1076 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.847779  1076 rpc_server.cc:307] RPC server started. Bound to: 127.1.13.1:41731
I20260812 06:18:43.847811  1345 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.13.1:41731 every 8 connection(s)
I20260812 06:18:43.858800  1346 heartbeater.cc:344] Connected to a master server at 127.1.13.62:35563
I20260812 06:18:43.859079  1346 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.859572  1346 heartbeater.cc:507] Master 127.1.13.62:35563 requested a full tablet report, sending...
I20260812 06:18:43.861148  1124 ts_manager.cc:194] Registered new tserver with Master: 935d7877fdab43788aaea6895ea21eac (127.1.13.1:41731)
I20260812 06:18:43.862037  1076 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013542986s
I20260812 06:18:43.862317  1124 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48760
I20260812 06:18:43.872220  1124 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48774:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:43.887126  1281 tablet_service.cc:1511] Processing CreateTablet for tablet 92a769826a6e480d96797d3652e0545a (DEFAULT_TABLE table=heavy-update-compaction-test [id=026f179c53e64cd58c4ddf8bb0ea4742]), partition=
I20260812 06:18:43.887643  1281 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 92a769826a6e480d96797d3652e0545a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.890249  1367 tablet_bootstrap.cc:492] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Bootstrap starting.
I20260812 06:18:43.891343  1367 tablet_bootstrap.cc:654] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.892696  1367 tablet_bootstrap.cc:492] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: No bootstrap required, opened a new log
I20260812 06:18:43.892817  1367 ts_tablet_manager.cc:1403] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:43.893289  1367 raft_consensus.cc:359] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "935d7877fdab43788aaea6895ea21eac" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 41731 } }
I20260812 06:18:43.893422  1367 raft_consensus.cc:385] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.893473  1367 raft_consensus.cc:740] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 935d7877fdab43788aaea6895ea21eac, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.893627  1367 consensus_queue.cc:260] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [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: "935d7877fdab43788aaea6895ea21eac" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 41731 } }
I20260812 06:18:43.893735  1367 raft_consensus.cc:399] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.893784  1367 raft_consensus.cc:493] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.893838  1367 raft_consensus.cc:3060] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.894652  1367 raft_consensus.cc:515] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "935d7877fdab43788aaea6895ea21eac" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 41731 } }
I20260812 06:18:43.894819  1367 leader_election.cc:304] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [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: 935d7877fdab43788aaea6895ea21eac; no voters: 
I20260812 06:18:43.895062  1367 leader_election.cc:290] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.895174  1371 raft_consensus.cc:2804] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.895426  1371 raft_consensus.cc:697] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 1 LEADER]: Becoming Leader. State: Replica: 935d7877fdab43788aaea6895ea21eac, State: Running, Role: LEADER
I20260812 06:18:43.895685  1346 heartbeater.cc:499] Master 127.1.13.62:35563 was elected leader, sending a full tablet report...
I20260812 06:18:43.895650  1371 consensus_queue.cc:237] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [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: "935d7877fdab43788aaea6895ea21eac" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 41731 } }
I20260812 06:18:43.895491  1367 ts_tablet_manager.cc:1434] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:43.898732  1124 catalog_manager.cc:5719] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac reported cstate change: term changed from 0 to 1, leader changed from <none> to 935d7877fdab43788aaea6895ea21eac (127.1.13.1). New cstate: current_term: 1 leader_uuid: "935d7877fdab43788aaea6895ea21eac" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "935d7877fdab43788aaea6895ea21eac" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 41731 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.968724  1076 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.022s	sys 0.007s
I20260812 06:18:44.098976  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushMRSOp(92a769826a6e480d96797d3652e0545a): perf score=15.086190
I20260812 06:18:44.237226  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushMRSOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.138s	user 0.117s	sys 0.020s Metrics: {"bytes_written":9148635,"cfile_init":1,"compiler_manager_pool.queue_time_us":225,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":860,"drs_written":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33245,"lbm_writes_lt_1ms":590,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":166400,"thread_start_us":129,"threads_started":1,"update_count":1115}
I20260812 06:18:44.239097  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling LogGCOp(92a769826a6e480d96797d3652e0545a): free 20743880 bytes of WAL
I20260812 06:18:44.239663  1243 log_reader.cc:385] T 92a769826a6e480d96797d3652e0545a: removed 2 log segments from log reader
I20260812 06:18:44.239784  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000001 (ops 1-6)
I20260812 06:18:44.239943  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000002 (ops 7-11)
I20260812 06:18:44.246531  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: LogGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:44.246959  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=1.196750
I20260812 06:18:44.273061  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.026s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3159084,"delete_count":0,"lbm_write_time_us":3985,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:18:44.273625  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:44.283946  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.284426  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a): 12719216 bytes on disk
I20260812 06:18:44.285001  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.285390  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:44.429674  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.144s	user 0.091s	sys 0.046s Metrics: {"cfile_cache_miss":423,"cfile_cache_miss_bytes":20262124,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1040,"lbm_read_time_us":9274,"lbm_reads_lt_1ms":459,"lbm_write_time_us":25263,"lbm_writes_lt_1ms":433,"mutex_wait_us":295,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":327,"threads_started":5,"update_count":1950}
I20260812 06:18:44.430294  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:44.477209  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.047s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18148,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.477691  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:44.488754  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.489351  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:44.603832  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.114s	user 0.092s	sys 0.022s 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":172,"lbm_read_time_us":8115,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23449,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:18:44.604460  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:44.657757  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16358,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.658375  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:44.675086  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.017s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.675683  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:44.835095  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.159s	user 0.111s	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":1441,"lbm_read_time_us":12803,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25969,"lbm_writes_lt_1ms":443,"mutex_wait_us":457,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:44.835587  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:44.884856  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.049s	user 0.036s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18439,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.885407  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:44.900732  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5629,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.901399  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.030944  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.129s	user 0.106s	sys 0.020s 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":268,"lbm_read_time_us":9161,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27069,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:18:45.031565  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:45.075284  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.043s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17361,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.075719  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:45.086362  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.086987  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.205399  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.118s	user 0.099s	sys 0.019s 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":243,"lbm_read_time_us":8388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22935,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:18:45.205966  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:45.250260  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.044s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15414,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.250803  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:45.265729  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.266201  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.389523  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.123s	user 0.095s	sys 0.028s 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":205,"lbm_read_time_us":9181,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23784,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:45.390131  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:45.435657  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.045s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14349,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.436205  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:45.446826  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.447250  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.597118  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.150s	user 0.093s	sys 0.056s 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":186,"lbm_read_time_us":11812,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23315,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:18:45.597877  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:45.638902  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.041s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16351,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.639391  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:45.651196  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.653666  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushMRSOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.690932  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushMRSOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.037s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":1511,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1815,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:45.691811  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling LogGCOp(92a769826a6e480d96797d3652e0545a): free 124257247 bytes of WAL
I20260812 06:18:45.692102  1243 log_reader.cc:385] T 92a769826a6e480d96797d3652e0545a: removed 12 log segments from log reader
I20260812 06:18:45.692173  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000003 (ops 12-16)
I20260812 06:18:45.692226  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000004 (ops 17-21)
I20260812 06:18:45.692263  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000005 (ops 22-26)
I20260812 06:18:45.692302  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000006 (ops 27-31)
I20260812 06:18:45.692337  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000007 (ops 32-36)
I20260812 06:18:45.692375  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000008 (ops 37-41)
I20260812 06:18:45.692410  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000009 (ops 42-46)
I20260812 06:18:45.692448  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000010 (ops 47-51)
I20260812 06:18:45.692507  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000011 (ops 52-56)
I20260812 06:18:45.692544  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000012 (ops 57-61)
I20260812 06:18:45.692580  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000013 (ops 62-66)
I20260812 06:18:45.692634  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000014 (ops 67-70)
I20260812 06:18:45.722232  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: LogGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:45.722797  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=4.173312
I20260812 06:18:45.750656  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.028s	user 0.010s	sys 0.015s Metrics: {"bytes_written":6112849,"delete_count":0,"lbm_write_time_us":7937,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:18:45.751266  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.758968  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.007s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2555,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:18:45.759555  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:45.977423  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.218s	user 0.148s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877292,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1971,"lbm_read_time_us":17268,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36187,"lbm_writes_lt_1ms":643,"mutex_wait_us":957,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:18:45.978453  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=14.095187
I20260812 06:18:46.053136  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.074s	user 0.038s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26944,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.053764  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:46.065850  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.066423  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a): 482 bytes on disk
I20260812 06:18:46.067077  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a) 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:18:46.067715  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:46.234699  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.167s	user 0.131s	sys 0.036s 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":937,"lbm_read_time_us":12718,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29569,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:18:46.235540  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=11.118625
I20260812 06:18:46.275067  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.039s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17314,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.275645  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:46.292752  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6212,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.293229  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:46.422225  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.129s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":8904,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24640,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:18:46.422894  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:46.466003  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.041s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14489,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.466450  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:46.476776  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.477236  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:46.606420  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.129s	user 0.108s	sys 0.020s 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":1293,"lbm_read_time_us":9710,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24372,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:18:46.607204  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:46.646129  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.039s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14845,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.646884  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:46.663399  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.664093  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:46.790747  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.126s	user 0.102s	sys 0.024s 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":1142,"lbm_read_time_us":9131,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24437,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:46.791366  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:46.853039  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.061s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14959,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.853675  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:46.872329  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.873034  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.029973  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.157s	user 0.096s	sys 0.060s 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":530,"lbm_read_time_us":12988,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26749,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:18:47.030699  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=11.118625
I20260812 06:18:47.065651  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.035s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12635684,"delete_count":0,"lbm_write_time_us":14928,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1540}
I20260812 06:18:47.066203  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:47.082383  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5880,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:47.082846  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.202443  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.119s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":8737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23871,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:47.203115  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:47.242921  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.040s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16669,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.243464  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:47.258473  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.259533  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushMRSOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.288259  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushMRSOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":142,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1390,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1491,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:47.289004  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling LogGCOp(92a769826a6e480d96797d3652e0545a): free 129320482 bytes of WAL
I20260812 06:18:47.289234  1243 log_reader.cc:385] T 92a769826a6e480d96797d3652e0545a: removed 13 log segments from log reader
I20260812 06:18:47.289279  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000015 (ops 71-75)
I20260812 06:18:47.289309  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000016 (ops 76-80)
I20260812 06:18:47.289371  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000017 (ops 81-85)
I20260812 06:18:47.289412  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000018 (ops 86-90)
I20260812 06:18:47.289453  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000019 (ops 91-95)
I20260812 06:18:47.289492  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000020 (ops 96-100)
I20260812 06:18:47.289535  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000021 (ops 101-104)
I20260812 06:18:47.289577  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000022 (ops 105-109)
I20260812 06:18:47.289636  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000023 (ops 110-114)
I20260812 06:18:47.289672  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000024 (ops 115-119)
I20260812 06:18:47.289724  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000025 (ops 120-124)
I20260812 06:18:47.289764  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000026 (ops 125-128)
I20260812 06:18:47.289803  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000027 (ops 129-133)
I20260812 06:18:47.319222  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: LogGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:47.319612  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=3.181125
I20260812 06:18:47.333636  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5561,"lbm_writes_lt_1ms":131,"mutex_wait_us":38,"reinsert_count":0,"update_count":640}
I20260812 06:18:47.334123  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a): 483 bytes on disk
I20260812 06:18:47.334540  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.335052  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=1.196750
I20260812 06:18:47.347235  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:18:47.347694  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.508394  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.161s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":774,"lbm_read_time_us":13019,"lbm_reads_lt_1ms":666,"lbm_write_time_us":30763,"lbm_writes_lt_1ms":643,"mutex_wait_us":79,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:18:47.508976  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=14.095187
I20260812 06:18:47.570112  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.061s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23468,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.570575  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:47.583611  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.584115  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.739836  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.156s	user 0.136s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":941,"lbm_read_time_us":10894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31868,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:47.740543  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=11.118625
I20260812 06:18:47.782604  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19799,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:47.783519  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:47.803224  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.020s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4703,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.803814  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:47.814453  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.815089  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:47.968798  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.153s	user 0.120s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1185,"lbm_read_time_us":12070,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31456,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.969511  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:48.008512  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.038s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14928,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.010579  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.027338  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.027832  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:48.172677  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.145s	user 0.110s	sys 0.032s 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":564,"lbm_read_time_us":11708,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28286,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:48.173256  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=10.126437
I20260812 06:18:48.214654  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.041s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14130,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.215219  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.236375  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.021s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.236927  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:48.395164  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.158s	user 0.103s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":9120,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26550,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.396127  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=14.095187
I20260812 06:18:48.448434  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.052s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19660,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:48.449079  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.464357  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.464917  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:48.641000  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.176s	user 0.126s	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":168,"lbm_read_time_us":12353,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29154,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:48.641693  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=14.095187
I20260812 06:18:48.692246  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.050s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409947,"delete_count":0,"lbm_write_time_us":22765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.692826  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.704015  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.704676  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushMRSOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:48.731472  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushMRSOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.027s	user 0.023s	sys 0.001s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1380,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1529,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:48.732307  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling LogGCOp(92a769826a6e480d96797d3652e0545a): free 121006757 bytes of WAL
I20260812 06:18:48.732621  1243 log_reader.cc:385] T 92a769826a6e480d96797d3652e0545a: removed 12 log segments from log reader
I20260812 06:18:48.732678  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000028 (ops 134-138)
I20260812 06:18:48.732717  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000029 (ops 139-143)
I20260812 06:18:48.732745  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000030 (ops 144-148)
I20260812 06:18:48.732775  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000031 (ops 149-153)
I20260812 06:18:48.732808  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000032 (ops 154-158)
I20260812 06:18:48.732837  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000033 (ops 159-163)
I20260812 06:18:48.732867  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000034 (ops 164-168)
I20260812 06:18:48.732889  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000035 (ops 169-173)
I20260812 06:18:48.732913  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000036 (ops 174-178)
I20260812 06:18:48.732939  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000037 (ops 179-182)
I20260812 06:18:48.732971  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000038 (ops 183-187)
I20260812 06:18:48.733008  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000039 (ops 188-192)
I20260812 06:18:48.764912  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: LogGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.032s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:48.765410  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a): 472 bytes on disk
I20260812 06:18:48.766021  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: UndoDeltaBlockGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.766638  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.798245  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.031s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.798929  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling LogGCOp(92a769826a6e480d96797d3652e0545a): free 11564893 bytes of WAL
I20260812 06:18:48.799209  1243 log_reader.cc:385] T 92a769826a6e480d96797d3652e0545a: removed 1 log segments from log reader
I20260812 06:18:48.799291  1243 log.cc:1079] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/92a769826a6e480d96797d3652e0545a/wal-000000040 (ops 193-196)
I20260812 06:18:48.801906  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: LogGCOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:48.802279  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a): perf score=2.188937
I20260812 06:18:48.822211  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: FlushDeltaMemStoresOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.020s	user 0.009s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.822968  1347 maintenance_manager.cc:419] P 935d7877fdab43788aaea6895ea21eac: Scheduling MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a): perf score=1.000000
I20260812 06:18:48.923146  1076 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.954s	user 1.887s	sys 0.130s
I20260812 06:18:49.029254  1076 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.105s	user 0.003s	sys 0.000s
I20260812 06:18:49.029876  1076 tablet_server.cc:179] TabletServer@127.1.13.1:0 shutting down...
I20260812 06:18:49.038053  1243 maintenance_manager.cc:643] P 935d7877fdab43788aaea6895ea21eac: MajorDeltaCompactionOp(92a769826a6e480d96797d3652e0545a) complete. Timing: real 0.215s	user 0.123s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979794,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":7137,"lbm_read_time_us":16329,"lbm_reads_lt_1ms":770,"lbm_write_time_us":34278,"lbm_writes_lt_1ms":743,"mutex_wait_us":3756,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":155,"threads_started":1,"update_count":3500}
I20260812 06:18:49.038699  1076 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:49.039800  1076 tablet_replica.cc:333] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac: stopping tablet replica
I20260812 06:18:49.040012  1076 raft_consensus.cc:2243] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.040233  1076 raft_consensus.cc:2272] T 92a769826a6e480d96797d3652e0545a P 935d7877fdab43788aaea6895ea21eac [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.047302  1076 tablet_server.cc:196] TabletServer@127.1.13.1:0 shutdown complete.
I20260812 06:18:49.094928  1076 master.cc:562] Master@127.1.13.62:35563 shutting down...
I20260812 06:18:49.099151  1076 raft_consensus.cc:2243] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:49.099365  1076 raft_consensus.cc:2272] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:49.099468  1076 tablet_replica.cc:333] T 00000000000000000000000000000000 P dd1fe9eedd324292b5c975301dbb216d: stopping tablet replica
I20260812 06:18:49.112135  1076 master.cc:584] Master@127.1.13.62:35563 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5520 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:49.214612  1076 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.13.62:46377
I20260812 06:18:49.215077  1076 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:49.217464  1403 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:49.217559  1076 server_base.cc:1061] running on GCE node
W20260812 06:18:49.217468  1401 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:49.217464  1400 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:49.217924  1076 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:49.217972  1076 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:49.217988  1076 hybrid_clock.cc:648] HybridClock initialized: now 1786515529217988 us; error 0 us; skew 500 ppm
I20260812 06:18:49.219017  1076 webserver.cc:533] Webserver started at http://127.1.13.62:45147/ using document root <none> and password file <none>
I20260812 06:18:49.219241  1076 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:49.219295  1076 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:49.219400  1076 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:49.219894  1076 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/master-0-root/instance:
uuid: "c2bbbb50cfcb441e80cc49b1325872b3"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-44d2"
I20260812 06:18:49.224901  1076 fs_manager.cc:696] Time spent creating directory manager: real 0.005s	user 0.003s	sys 0.000s
I20260812 06:18:49.234225  1408 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.234618  1076 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:49.234724  1076 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/master-0-root
uuid: "c2bbbb50cfcb441e80cc49b1325872b3"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-44d2"
I20260812 06:18:49.234822  1076 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:49.245558  1076 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:49.246125  1076 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:49.251581  1076 rpc_server.cc:307] RPC server started. Bound to: 127.1.13.62:46377
I20260812 06:18:49.255295  1493 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:49.255648  1492 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.13.62:46377 every 8 connection(s)
I20260812 06:18:49.259370  1493 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3: Bootstrap starting.
I20260812 06:18:49.260232  1493 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:49.261442  1493 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3: No bootstrap required, opened a new log
I20260812 06:18:49.261917  1493 raft_consensus.cc:359] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER }
I20260812 06:18:49.262059  1493 raft_consensus.cc:385] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:49.262125  1493 raft_consensus.cc:740] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c2bbbb50cfcb441e80cc49b1325872b3, State: Initialized, Role: FOLLOWER
I20260812 06:18:49.262298  1493 consensus_queue.cc:260] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [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: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER }
I20260812 06:18:49.262382  1493 raft_consensus.cc:399] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:49.262405  1493 raft_consensus.cc:493] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:49.262435  1493 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:49.263131  1493 raft_consensus.cc:515] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER }
I20260812 06:18:49.263266  1493 leader_election.cc:304] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [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: c2bbbb50cfcb441e80cc49b1325872b3; no voters: 
I20260812 06:18:49.263466  1493 leader_election.cc:290] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:49.263588  1497 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:49.263777  1497 raft_consensus.cc:697] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 1 LEADER]: Becoming Leader. State: Replica: c2bbbb50cfcb441e80cc49b1325872b3, State: Running, Role: LEADER
I20260812 06:18:49.263921  1497 consensus_queue.cc:237] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [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: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER }
I20260812 06:18:49.264019  1493 sys_catalog.cc:565] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:49.264371  1497 sys_catalog.cc:455] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c2bbbb50cfcb441e80cc49b1325872b3. Latest consensus state: current_term: 1 leader_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER } }
I20260812 06:18:49.264371  1498 sys_catalog.cc:455] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c2bbbb50cfcb441e80cc49b1325872b3" member_type: VOTER } }
I20260812 06:18:49.264508  1497 sys_catalog.cc:458] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:49.264524  1498 sys_catalog.cc:458] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:49.265463  1502 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:49.266659  1502 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:49.266861  1076 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:49.268702  1502 catalog_manager.cc:1383] Generated new cluster ID: 6c860b17a50c41d1b070091271a2802f
I20260812 06:18:49.268757  1502 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:49.283610  1502 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:49.284235  1502 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:49.293490  1502 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3: Generated new TSK 0
I20260812 06:18:49.293704  1502 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:49.299256  1076 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:49.301944  1531 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:18:49.302119  1076 server_base.cc:1061] running on GCE node
W20260812 06:18:49.302299  1537 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:49.302542  1529 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:49.302834  1076 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:49.302896  1076 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:49.302923  1076 hybrid_clock.cc:648] HybridClock initialized: now 1786515529302923 us; error 0 us; skew 500 ppm
I20260812 06:18:49.304061  1076 webserver.cc:533] Webserver started at http://127.1.13.1:40779/ using document root <none> and password file <none>
I20260812 06:18:49.304265  1076 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:49.304350  1076 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:49.304440  1076 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:49.305053  1076 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/instance:
uuid: "889408c7eca346cd808671d0d9629802"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-44d2"
I20260812 06:18:49.307435  1076 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:49.308724  1545 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.309082  1076 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:49.309176  1076 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root
uuid: "889408c7eca346cd808671d0d9629802"
format_stamp: "Formatted at 2026-08-12 06:18:49 on dist-test-slave-44d2"
I20260812 06:18:49.309270  1076 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:49.327040  1076 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:49.327458  1076 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:49.327821  1076 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:49.328341  1076 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:49.328404  1076 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.328470  1076 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:49.328532  1076 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:49.333464  1076 rpc_server.cc:307] RPC server started. Bound to: 127.1.13.1:35867
I20260812 06:18:49.334549  1640 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.13.1:35867 every 8 connection(s)
I20260812 06:18:49.344096  1641 heartbeater.cc:344] Connected to a master server at 127.1.13.62:46377
I20260812 06:18:49.344237  1641 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:49.344537  1641 heartbeater.cc:507] Master 127.1.13.62:46377 requested a full tablet report, sending...
I20260812 06:18:49.345239  1437 ts_manager.cc:194] Registered new tserver with Master: 889408c7eca346cd808671d0d9629802 (127.1.13.1:35867)
I20260812 06:18:49.345788  1076 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011322911s
I20260812 06:18:49.346055  1437 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57340
I20260812 06:18:49.354211  1437 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57348:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:49.364337  1588 tablet_service.cc:1511] Processing CreateTablet for tablet 577ddf4c8c544af5ba4e60b2b67af01e (DEFAULT_TABLE table=heavy-update-compaction-test [id=b547a609886643029f3629793d957c82]), partition=
I20260812 06:18:49.364702  1588 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 577ddf4c8c544af5ba4e60b2b67af01e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:49.367123  1659 tablet_bootstrap.cc:492] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Bootstrap starting.
I20260812 06:18:49.368219  1659 tablet_bootstrap.cc:654] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:49.369527  1659 tablet_bootstrap.cc:492] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: No bootstrap required, opened a new log
I20260812 06:18:49.369637  1659 ts_tablet_manager.cc:1403] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:49.370039  1659 raft_consensus.cc:359] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "889408c7eca346cd808671d0d9629802" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 35867 } }
I20260812 06:18:49.370150  1659 raft_consensus.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:49.370195  1659 raft_consensus.cc:740] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 889408c7eca346cd808671d0d9629802, State: Initialized, Role: FOLLOWER
I20260812 06:18:49.370337  1659 consensus_queue.cc:260] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [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: "889408c7eca346cd808671d0d9629802" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 35867 } }
I20260812 06:18:49.370447  1659 raft_consensus.cc:399] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:49.370494  1659 raft_consensus.cc:493] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:49.370556  1659 raft_consensus.cc:3060] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:49.371271  1659 raft_consensus.cc:515] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "889408c7eca346cd808671d0d9629802" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 35867 } }
I20260812 06:18:49.371428  1659 leader_election.cc:304] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [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: 889408c7eca346cd808671d0d9629802; no voters: 
I20260812 06:18:49.371644  1659 leader_election.cc:290] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:49.371775  1661 raft_consensus.cc:2804] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:49.371990  1659 ts_tablet_manager.cc:1434] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:49.372021  1661 raft_consensus.cc:697] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 1 LEADER]: Becoming Leader. State: Replica: 889408c7eca346cd808671d0d9629802, State: Running, Role: LEADER
I20260812 06:18:49.372051  1641 heartbeater.cc:499] Master 127.1.13.62:46377 was elected leader, sending a full tablet report...
I20260812 06:18:49.372166  1661 consensus_queue.cc:237] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [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: "889408c7eca346cd808671d0d9629802" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 35867 } }
I20260812 06:18:49.374547  1437 catalog_manager.cc:5719] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 reported cstate change: term changed from 0 to 1, leader changed from <none> to 889408c7eca346cd808671d0d9629802 (127.1.13.1). New cstate: current_term: 1 leader_uuid: "889408c7eca346cd808671d0d9629802" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "889408c7eca346cd808671d0d9629802" member_type: VOTER last_known_addr { host: "127.1.13.1" port: 35867 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:49.438992  1076 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.019s	sys 0.004s
I20260812 06:18:49.585351  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=19.054940
I20260812 06:18:49.790355  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.205s	user 0.151s	sys 0.035s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":871,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46816,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":21120,"update_count":1500}
I20260812 06:18:49.791083  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e): free 20743880 bytes of WAL
I20260812 06:18:49.791330  1553 log_reader.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e: removed 2 log segments from log reader
I20260812 06:18:49.791427  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000001 (ops 1-6)
I20260812 06:18:49.791505  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000002 (ops 7-11)
I20260812 06:18:49.797514  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:49.797919  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e): 16411396 bytes on disk
I20260812 06:18:49.798405  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.798833  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:49.818109  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.019s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.818562  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:49.979584  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.161s	user 0.135s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":63,"lbm_read_time_us":11944,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26558,"lbm_writes_lt_1ms":443,"mutex_wait_us":343,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":322,"threads_started":5,"update_count":2000}
I20260812 06:18:49.980212  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=11.118625
I20260812 06:18:50.039238  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.059s	user 0.028s	sys 0.028s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20985,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:50.039853  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:50.069813  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.030s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6046,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.070320  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:50.085341  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5905,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.085924  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:50.294688  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.208s	user 0.141s	sys 0.064s 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":1004,"lbm_read_time_us":18164,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30165,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:50.295441  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:50.351666  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.055s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15762,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.352317  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:50.364267  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.364862  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:50.557919  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.193s	user 0.122s	sys 0.060s 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":322,"lbm_read_time_us":13191,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28599,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2000}
I20260812 06:18:50.558542  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:50.611495  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.053s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17211,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.612059  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:50.628355  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.629058  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:50.782096  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.153s	user 0.132s	sys 0.020s 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":972,"lbm_read_time_us":11055,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29833,"lbm_writes_lt_1ms":443,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:18:50.782790  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:50.829975  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.047s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15353,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.830513  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:50.841475  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.842244  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:50.982610  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.140s	user 0.094s	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":741,"lbm_read_time_us":8784,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24057,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:50.983220  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:51.030349  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.047s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.031181  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:51.176900  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.145s	user 0.085s	sys 0.055s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":537,"lbm_read_time_us":9642,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22308,"lbm_writes_lt_1ms":343,"mutex_wait_us":79,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.177619  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=11.118625
I20260812 06:18:51.225369  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.046s	user 0.025s	sys 0.016s Metrics: {"bytes_written":13004907,"delete_count":0,"lbm_write_time_us":19300,"lbm_writes_lt_1ms":320,"reinsert_count":0,"update_count":1585}
I20260812 06:18:51.225970  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:51.241747  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:51.242290  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:51.256389  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5237,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.256889  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:51.295064  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.038s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1297,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2327,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:51.295804  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e): free 115943174 bytes of WAL
I20260812 06:18:51.296083  1553 log_reader.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e: removed 11 log segments from log reader
I20260812 06:18:51.296149  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000003 (ops 12-16)
I20260812 06:18:51.296185  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000004 (ops 17-21)
I20260812 06:18:51.296216  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000005 (ops 22-26)
I20260812 06:18:51.296250  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000006 (ops 27-31)
I20260812 06:18:51.296285  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000007 (ops 32-36)
I20260812 06:18:51.296307  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000008 (ops 37-41)
I20260812 06:18:51.296336  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000009 (ops 42-46)
I20260812 06:18:51.296365  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000010 (ops 47-51)
I20260812 06:18:51.296396  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000011 (ops 52-56)
I20260812 06:18:51.296429  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000012 (ops 57-61)
I20260812 06:18:51.296463  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000013 (ops 62-66)
I20260812 06:18:51.326861  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.031s	user 0.003s	sys 0.026s Metrics: {}
I20260812 06:18:51.327395  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e): 462 bytes on disk
I20260812 06:18:51.328357  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e) 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:18:51.329098  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:51.355844  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.027s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":5300,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:51.356468  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:51.367833  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4408,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:51.368286  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:51.619153  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.251s	user 0.156s	sys 0.090s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":337,"lbm_read_time_us":15619,"lbm_reads_lt_1ms":775,"lbm_write_time_us":44653,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17280,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:18:51.622628  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=15.087375
I20260812 06:18:51.683295  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22063,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:51.683880  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=3.181125
I20260812 06:18:51.697204  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4430857,"delete_count":0,"lbm_write_time_us":4734,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:51.697680  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:51.711055  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:18:51.711591  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:51.943971  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.232s	user 0.157s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1225,"lbm_read_time_us":16583,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39965,"lbm_writes_lt_1ms":643,"mutex_wait_us":571,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:18:51.944578  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=14.095187
I20260812 06:18:52.021507  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.077s	user 0.028s	sys 0.033s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.021984  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:52.032793  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.010s	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:18:52.033216  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:52.242812  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.209s	user 0.141s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":539,"lbm_read_time_us":13223,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32895,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:18:52.243803  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=11.118625
I20260812 06:18:52.302418  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.055s	user 0.030s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17653,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:52.303107  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:52.317401  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5549,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.317950  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:52.500707  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.183s	user 0.124s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1327,"lbm_read_time_us":12516,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28937,"lbm_writes_lt_1ms":443,"mutex_wait_us":601,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:52.501291  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:52.546561  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.547115  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:52.558130  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.558634  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:52.688405  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.130s	user 0.101s	sys 0.028s 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":915,"lbm_read_time_us":9168,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24399,"lbm_writes_lt_1ms":443,"mutex_wait_us":359,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:18:52.689174  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=6.157687
I20260812 06:18:52.717361  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.028s	user 0.012s	sys 0.015s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11845,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:52.718029  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:52.823139  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.105s	user 0.072s	sys 0.031s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12467334,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":3037,"lbm_read_time_us":7713,"lbm_reads_lt_1ms":267,"lbm_write_time_us":16034,"lbm_writes_lt_1ms":243,"mutex_wait_us":2458,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":1000}
I20260812 06:18:52.823961  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=7.149875
I20260812 06:18:52.858949  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.035s	user 0.019s	sys 0.011s Metrics: {"bytes_written":8615325,"delete_count":0,"lbm_write_time_us":14139,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:52.859493  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:52.873139  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5408,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.873657  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.015293  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.141s	user 0.101s	sys 0.039s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":8551,"lbm_reads_lt_1ms":372,"lbm_write_time_us":25236,"lbm_writes_lt_1ms":343,"mutex_wait_us":3,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.016018  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=6.157687
I20260812 06:18:53.058197  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.041s	user 0.022s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":13018,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:53.058950  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:53.077384  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.018s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6648,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.077940  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.117331  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.039s	user 0.034s	sys 0.004s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1558,"drs_written":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2460,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:53.118535  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e): free 124710318 bytes of WAL
I20260812 06:18:53.118865  1553 log_reader.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e: removed 12 log segments from log reader
I20260812 06:18:53.118968  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000014 (ops 67-71)
I20260812 06:18:53.119035  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000015 (ops 72-76)
I20260812 06:18:53.119071  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000016 (ops 77-81)
I20260812 06:18:53.119167  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000017 (ops 82-86)
I20260812 06:18:53.119227  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000018 (ops 87-91)
I20260812 06:18:53.119333  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000019 (ops 92-96)
I20260812 06:18:53.119400  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000020 (ops 97-101)
I20260812 06:18:53.119501  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000021 (ops 102-106)
I20260812 06:18:53.119568  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000022 (ops 107-111)
I20260812 06:18:53.119663  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000023 (ops 112-116)
I20260812 06:18:53.119720  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000024 (ops 117-121)
I20260812 06:18:53.119822  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000025 (ops 122-126)
I20260812 06:18:53.153936  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.035s	user 0.003s	sys 0.031s Metrics: {}
I20260812 06:18:53.154541  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e): 461 bytes on disk
I20260812 06:18:53.155213  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.155818  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=4.173312
I20260812 06:18:53.175689  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":6235917,"delete_count":0,"lbm_write_time_us":8569,"lbm_writes_lt_1ms":155,"reinsert_count":0,"update_count":760}
I20260812 06:18:53.176229  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.182583  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":1975,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:18:53.183044  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.362947  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.180s	user 0.111s	sys 0.067s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24774874,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":664,"lbm_read_time_us":13906,"lbm_reads_lt_1ms":574,"lbm_write_time_us":31251,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":93,"threads_started":1,"update_count":2500}
I20260812 06:18:53.363631  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:53.409027  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.045s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20031,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.409546  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.563256  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.154s	user 0.095s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":266,"lbm_read_time_us":9869,"lbm_reads_lt_1ms":367,"lbm_write_time_us":23214,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.564014  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=14.095187
I20260812 06:18:53.623497  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.059s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22720,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:53.624110  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:53.641777  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6874,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.642570  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:53.823690  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.181s	user 0.125s	sys 0.055s 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":157,"lbm_read_time_us":14612,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31924,"lbm_writes_lt_1ms":543,"mutex_wait_us":358,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2500}
I20260812 06:18:53.824522  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:53.877925  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.053s	user 0.049s	sys 0.002s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24430,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:53.878481  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:53.895047  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:53.896081  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:54.035748  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.136s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":8997,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26305,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:54.036609  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:54.091825  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.055s	user 0.028s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22095,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.092553  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:54.104282  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.104847  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:54.232924  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.128s	user 0.108s	sys 0.019s 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":73,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25577,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:18:54.233738  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=7.149875
I20260812 06:18:54.270714  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.037s	user 0.025s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14805,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:54.271570  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:54.298259  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.026s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6219,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.298839  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:54.468659  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.170s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1015,"lbm_read_time_us":11617,"lbm_reads_lt_1ms":372,"lbm_write_time_us":25333,"lbm_writes_lt_1ms":343,"mutex_wait_us":318,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":1500}
I20260812 06:18:54.469205  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:54.515305  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.046s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17143,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.515828  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:54.531101  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.531680  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:54.682602  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.151s	user 0.111s	sys 0.028s 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":652,"lbm_read_time_us":9389,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26860,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:18:54.683239  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=10.126437
I20260812 06:18:54.725346  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.042s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17193,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.725932  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:54.779196  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushMRSOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.053s	user 0.036s	sys 0.002s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1558,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1789,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:54.779948  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e): free 108988743 bytes of WAL
I20260812 06:18:54.780191  1553 log_reader.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e: removed 11 log segments from log reader
I20260812 06:18:54.780246  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000026 (ops 127-131)
I20260812 06:18:54.780318  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000027 (ops 132-136)
I20260812 06:18:54.780355  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000028 (ops 137-140)
I20260812 06:18:54.780385  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000029 (ops 141-145)
I20260812 06:18:54.780460  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000030 (ops 146-150)
I20260812 06:18:54.780526  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000031 (ops 151-155)
I20260812 06:18:54.780578  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000032 (ops 156-160)
I20260812 06:18:54.780609  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000033 (ops 161-165)
I20260812 06:18:54.780658  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000034 (ops 166-170)
I20260812 06:18:54.780687  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000035 (ops 171-175)
I20260812 06:18:54.780733  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000036 (ops 176-180)
I20260812 06:18:54.809507  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:54.810045  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e): 463 bytes on disk
I20260812 06:18:54.810614  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: UndoDeltaBlockGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.811187  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=7.149875
I20260812 06:18:54.831944  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.021s	user 0.015s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9292,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:54.832470  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e): free 11564893 bytes of WAL
I20260812 06:18:54.832738  1553 log_reader.cc:385] T 577ddf4c8c544af5ba4e60b2b67af01e: removed 1 log segments from log reader
I20260812 06:18:54.832800  1553 log.cc:1079] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: Deleting log segment in path: /tmp/dist-test-taskQPtMFi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515523669290-1076-0/minicluster-data/ts-0-root/wals/577ddf4c8c544af5ba4e60b2b67af01e/wal-000000037 (ops 181-184)
I20260812 06:18:54.835290  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: LogGCOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:54.835605  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:54.851857  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5256,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:54.852319  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:55.035034  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.183s	user 0.149s	sys 0.027s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877212,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":167,"lbm_read_time_us":12526,"lbm_reads_lt_1ms":669,"lbm_write_time_us":35448,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:55.035766  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=14.095187
I20260812 06:18:55.089100  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.053s	user 0.046s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.089602  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=2.188937
I20260812 06:18:55.100473  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.101027  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=1.000000
I20260812 06:18:55.198475  1076 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.759s	user 2.056s	sys 0.163s
I20260812 06:18:55.249336  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: MajorDeltaCompactionOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.148s	user 0.100s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11162,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30398,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:55.249864  1642 maintenance_manager.cc:419] P 889408c7eca346cd808671d0d9629802: Scheduling FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e): perf score=6.157687
I20260812 06:18:55.284468  1076 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.086s	user 0.001s	sys 0.000s
I20260812 06:18:55.285086  1076 tablet_server.cc:179] TabletServer@127.1.13.1:0 shutting down...
I20260812 06:18:55.310505  1553 maintenance_manager.cc:643] P 889408c7eca346cd808671d0d9629802: FlushDeltaMemStoresOp(577ddf4c8c544af5ba4e60b2b67af01e) complete. Timing: real 0.060s	user 0.010s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9944,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:55.311151  1076 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:55.311393  1076 tablet_replica.cc:333] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802: stopping tablet replica
I20260812 06:18:55.311590  1076 raft_consensus.cc:2243] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:55.311806  1076 raft_consensus.cc:2272] T 577ddf4c8c544af5ba4e60b2b67af01e P 889408c7eca346cd808671d0d9629802 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:55.316637  1076 tablet_server.cc:196] TabletServer@127.1.13.1:0 shutdown complete.
I20260812 06:18:55.321499  1076 master.cc:562] Master@127.1.13.62:46377 shutting down...
I20260812 06:18:55.328150  1076 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:55.328317  1076 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:55.328370  1076 tablet_replica.cc:333] T 00000000000000000000000000000000 P c2bbbb50cfcb441e80cc49b1325872b3: stopping tablet replica
I20260812 06:18:55.341244  1076 master.cc:584] Master@127.1.13.62:46377 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6234 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11755 ms total)

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